From f68a622ea0ab438f699fcd5e29f6c4167c59029e Mon Sep 17 00:00:00 2001 From: Tiago Gomes Date: Thu, 13 Aug 2015 15:07:50 +0000 Subject: Improve build logging Change-Id: If9a6b17797166c295f3c597cc6d17226d45957e7 --- morphlib/app.py | 15 ++++++++++----- morphlib/buildcommand.py | 40 ++++++++++++++++++++++++++++++---------- morphlib/builder.py | 45 ++++++++++++++------------------------------- morphlib/stagingarea.py | 3 +-- 4 files changed, 55 insertions(+), 48 deletions(-) diff --git a/morphlib/app.py b/morphlib/app.py index 8fd52a46..187675cd 100644 --- a/morphlib/app.py +++ b/morphlib/app.py @@ -342,7 +342,12 @@ class Morph(cliapp.Application): ''' assert 'msg' in kwargs - text = self.status_prefix + (kwargs['msg'] % kwargs) + msg = kwargs['msg'] % kwargs + + logger = logging.getLogger() + fmt = '%(asctime)s %(levelname)s ' + self.status_prefix + '%(message)s' + datefmt = self.setup_logging_timestamp() + logger.handlers[0].setFormatter(logging.Formatter(fmt, datefmt)) error = kwargs.get('error', False) chatty = kwargs.get('chatty', False) @@ -350,15 +355,15 @@ class Morph(cliapp.Application): debug = self.settings['debug'] if error: - logging.error(text) + logging.error(msg) elif chatty: - logging.debug(text) + logging.debug(msg) else: - logging.info(text) + logging.info(msg) ok = debug or error or (not quiet and not chatty) if ok: - self._write_status(text) + self._write_status("%s%s" % (self.status_prefix, msg)) def _commandline_as_message(self, argv, args): '''Create a status string for a command that's about to be executed.''' diff --git a/morphlib/buildcommand.py b/morphlib/buildcommand.py index bb354b2f..86cb8ff8 100644 --- a/morphlib/buildcommand.py +++ b/morphlib/buildcommand.py @@ -362,17 +362,21 @@ class BuildCommand(object): use_chroot = True setup_mounts = True - staging_area = self.create_staging_area(source, - build_env, - use_chroot, - extra_env=extra_env, - extra_path=extra_path) + staging_area, sa_log_handler = self.create_staging_area( + source, + build_env, + use_chroot, + extra_env=extra_env, + extra_path=extra_path) self.install_dependencies(staging_area, deps, source) else: - staging_area = self.create_staging_area(source, build_env, False) + staging_area, sa_log_handler = self.create_staging_area( + source, + build_env, + False) self.build_and_cache(staging_area, source, setup_mounts) - self.remove_staging_area(staging_area) + self.remove_staging_area(staging_area, sa_log_handler) td = datetime.datetime.now() - starttime hours, remainder = divmod(int(td.total_seconds()), 60*60) @@ -445,19 +449,35 @@ class BuildCommand(object): extra_env={}, extra_path=[]): '''Create the staging area for building a single artifact.''' - self.app.status(msg='Creating staging area') staging_dir = tempfile.mkdtemp( dir=os.path.join(self.app.settings['tempdir'], 'staging')) + + sa_log_handler = logging.FileHandler('%s.build-log' % staging_dir) + fmt = self.app.setup_logging_format() + datefmt = self.app.setup_logging_timestamp() + sa_log_handler.setFormatter(logging.Formatter(fmt, datefmt)) + logging.getLogger().addHandler(sa_log_handler) + # Configure the logger to only record DEBUG messages the staging area + # log file if the build failed, or in the chunk cache directory if the + # build succeded + logging.getLogger().handlers[0].setLevel(logging.INFO) + logging.getLogger().setLevel(logging.INFO) + + self.app.status(msg='Creating staging area') staging_area = morphlib.stagingarea.StagingArea( self.app, source, staging_dir, build_env, use_chroot, extra_env, extra_path) - return staging_area - def remove_staging_area(self, staging_area): + + return staging_area, sa_log_handler + + def remove_staging_area(self, staging_area, sa_log_handler): '''Remove the staging area.''' self.app.status(msg='Removing staging area') staging_area.remove() + logging.getLogger().removeHandler(sa_log_handler) + logging.getLogger().handlers[0].setLevel(logging.DEBUG) # Nasty hack to avoid installing chunks built in 'bootstrap' mode in a # different stratum when constructing staging areas. diff --git a/morphlib/builder.py b/morphlib/builder.py index 0e2142b3..378d8e97 100644 --- a/morphlib/builder.py +++ b/morphlib/builder.py @@ -282,27 +282,10 @@ class ChunkBuilder(BuilderBase): logpath = cache.get_source_metadata_filename( self.source, self.source.cache_key, 'build-log') - _, temppath = tempfile.mkstemp(dir=os.path.dirname(logpath)) - - try: - self.get_sources(builddir) - self.run_commands(temppath, stdout) - self.create_devices(destdir) - - os.rename(temppath, logpath) - except BaseException as e: - logging.error('Caught exception: %s' % str(e)) - logging.info('Cleaning up staging area') - if os.path.isfile(temppath): - with open(temppath) as f: - for line in f: - logging.error('BUILD OUTPUT: %s' % - line.rstrip('\n')) - - os.rename(temppath, logpath) - else: - logging.error("Couldn't find build log at %s", temppath) - raise + self.get_sources(builddir) + self.run_commands(stdout) + self.create_devices(destdir) + os.rename("%s.build-log" % self.staging_area.staging_dir, logpath) built_artifacts = self.assemble_chunk_artifacts(destdir) @@ -337,6 +320,7 @@ class ChunkBuilder(BuilderBase): ('strip', False), ('post-strip', False), ] + build_output = [] for step, in_parallel in steps: with self.build_watch(step): key = '%s-commands' % step @@ -344,9 +328,8 @@ class ChunkBuilder(BuilderBase): if not cmds: continue - with open(logfilepath, 'a') as log: - self.app.status(msg='Running %(key)s', key=key) - log.write('### %s ###\n' % key.upper()) + self.app.status(msg='Running %(key)s', key=key) + build_output.append('### %s ###\n' % key.upper()) for cmd in cmds: if cmd is False: cmd = "false" @@ -367,31 +350,31 @@ class ChunkBuilder(BuilderBase): stdout.flush() with open(os.devnull) as devnull: - exit_code = self.runcmd(['sh', '-x', '-c', cmd], + exit_code, out, err = 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) + build_output.append(out) if stdout: stdout.flush() + for line in ''.join(build_output).splitlines(): + logging.debug('[Build output] %s' % line) + if exit_code != 0: if not stdout: - with open(logfilepath, 'r') as log: - shutil.copyfileobj(log, self.app.output) + self.app.output.write(''.join(build_output)) 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 diff --git a/morphlib/stagingarea.py b/morphlib/stagingarea.py index 9ab87950..65355d8a 100644 --- a/morphlib/stagingarea.py +++ b/morphlib/stagingarea.py @@ -284,7 +284,6 @@ class StagingArea(object): exit, out, err = self._app.runcmd_unchecked(cmdline, **kwargs) if exit != 0: - logging.debug('Command returned code %i', exit) chroot_script = self.dirname + '.sh' shell_command = ['env', '-i', '--'] for k, v in kwargs['env'].iteritems(): @@ -294,6 +293,6 @@ class StagingArea(object): shell_command, **container_config) with open(chroot_script, 'w') as f: f.write(' '.join(map(pipes.quote, cmdline))) - return exit + return exit, out, err -- cgit v1.2.1