summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorTiago Gomes <tiago.gomes@codethink.co.uk>2015-08-13 15:07:50 (GMT)
committerTiago Gomes <tiago.gomes@codethink.co.uk>2015-09-01 15:19:06 (GMT)
commitf68a622ea0ab438f699fcd5e29f6c4167c59029e (patch)
tree96b5141c4783bce51c3ce2901dbebc7fa5383e69
parent29d6b3d36e40317ab72bd543b7d644161906b723 (diff)
downloadmorph-tiagogomes/improve-debugging.tar.gz
Improve build loggingtiagogomes/improve-debugging
Change-Id: If9a6b17797166c295f3c597cc6d17226d45957e7
-rw-r--r--morphlib/app.py15
-rw-r--r--morphlib/buildcommand.py40
-rw-r--r--morphlib/builder.py45
-rw-r--r--morphlib/stagingarea.py3
4 files changed, 55 insertions, 48 deletions
diff --git a/morphlib/app.py b/morphlib/app.py
index 8fd52a4..187675c 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 bb354b2..86cb8ff 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 0e2142b..378d8e9 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 9ab8795..65355d8 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