4:52 p.m.
repo: git://git.baserock.org/baserock/baserock/morph
ref: baserock/richardipsum/build-log-on-stdout-tee
head: ad47e5b8567ece69bda7358f6c8ce4868368c59f
Hi again,
This patch takes care of writing an artifact's build log to both stdout
and a build log file if the --build-log-on-stdout flag is set.
This series uses tee to write the output to a file as well as to stdout.
Using Popen it should be straight forward to send the output to a pipe and
then read that pipe and write to wherever (stdout plus a logfile in our case).
At the moment morph uses cliapp's runcmd rather than Popen. cliapp's runcmd
is a blocking call, so we're not able to read from the pipe until the
command has completed, which prevents real time logging to a number of files.
One solution to this problem might be to spawn a thread which opens a pipe
to the command being executed, the thread then reads from the pipe and writes
to our collection of logfiles, an attempt at this can be found at ref
baserock/richardipsum/build-log-on-stdout3
The test for the getter that was added to the local artifact cache may not
be worth adding: we may want to just use #pragma: no cover
Richard Ipsum (6):
Add get_source_metadata_filename
Add test for get_source_metadata_filename
Add --build-log-on-stdout flag
Add logfile kwarg to staging area runcmd
Use logfile kwarg to generate build log
Make distbuild put worker logs onto stdout
distbuild/worker_build_scheduler.py | 1 +
morphlib/app.py | 3 ++
morphlib/builder2.py | 71 ++++++++++++++++++++++------------
morphlib/localartifactcache.py | 5 ++-
morphlib/localartifactcache_tests.py | 11 ++++++
morphlib/stagingarea.py | 10 ++++-
6 files changed, 75 insertions(+), 26 deletions(-)
--
1.7.10.4
4:52 p.m.
New subject: [PATCH 1/6] Add get_source_metadata_filename
---
morphlib/localartifactcache.py | 5 ++++-
1 file changed, 4 insertions(+), 1 deletion(-)
diff --git a/morphlib/localartifactcache.py b/morphlib/localartifactcache.py
index 341bbb5..4c7f783 100644
--- a/morphlib/localartifactcache.py
+++ b/morphlib/localartifactcache.py
@@ -1,4 +1,4 @@
-# Copyright (C) 2012,2013 Codethink Limited
+# Copyright (C) 2012, 2013, 2014 Codethink Limited
#
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
@@ -88,6 +88,9 @@ class LocalArtifactCache(object):
os.utime(filename, None)
return open(filename)
+ def get_source_metadata_filename(self, source, cachekey, name):
+ return self._source_metadata_filename(source, cachekey, name)
+
def get_source_metadata(self, source, cachekey, name):
filename = self._source_metadata_filename(source, cachekey, name)
os.utime(filename, None)
--
1.7.10.4
4:52 p.m.
New subject: [PATCH 2/6] Add test for get_source_metadata_filename
---
morphlib/localartifactcache_tests.py | 11 +++++++++++
1 file changed, 11 insertions(+)
diff --git a/morphlib/localartifactcache_tests.py b/morphlib/localartifactcache_tests.py
index 18d2061..f400a64 100644
--- a/morphlib/localartifactcache_tests.py
+++ b/morphlib/localartifactcache_tests.py
@@ -60,6 +60,17 @@ class LocalArtifactCacheTests(unittest.TestCase):
expected_name = self.tempfs.getsyspath(self.devel_artifact.basename())
self.assertEqual(filename, expected_name)
+ def test_get_source_metadata_filename(self):
+ cache = morphlib.localartifactcache.LocalArtifactCache(self.tempfs)
+ artifact = self.devel_artifact
+ name = 'foobar'
+
+ filename = cache.get_source_metadata_filename(artifact.source,
+ artifact.cache_key, name)
+ expected_name = self.tempfs.getsyspath('%s.%s' %
+ (artifact.cache_key, name))
+ self.assertEqual(filename, expected_name)
+
def test_put_artifacts_and_check_whether_the_cache_has_them(self):
cache = morphlib.localartifactcache.LocalArtifactCache(self.tempfs)
--
1.7.10.4
4:52 p.m.
New subject: [PATCH 3/6] Add --build-log-on-stdout flag
---
morphlib/app.py | 3 +++
1 file changed, 3 insertions(+)
diff --git a/morphlib/app.py b/morphlib/app.py
index 91647a3..5b11d26 100644
--- a/morphlib/app.py
+++ b/morphlib/app.py
@@ -84,6 +84,9 @@ class Morph(cliapp.Application):
'do not update the cached git repositories '
'automatically',
group=group_advanced)
+ self.settings.boolean(['build-log-on-stdout'],
+ 'write build log on stdout',
+ group=group_advanced)
self.settings.string_list(['repo-alias'],
'list of URL prefix definitions, in the '
'form: example=git://git.example.com/%s'
--
1.7.10.4
4:52 p.m.
New subject: [PATCH 4/6] Add logfile kwarg to staging area runcmd
---
morphlib/stagingarea.py | 10 +++++++++-
1 file changed, 9 insertions(+), 1 deletion(-)
diff --git a/morphlib/stagingarea.py b/morphlib/stagingarea.py
index 61f9e66..ebbb79b 100644
--- a/morphlib/stagingarea.py
+++ b/morphlib/stagingarea.py
@@ -309,7 +309,15 @@ class StagingArea(object):
real_argv += argv
try:
- return self._app.runcmd(real_argv, **kwargs)
+ if 'logfile' in kwargs:
+ logfile = kwargs['logfile']
+ del kwargs['logfile']
+
+ if logfile:
+ teecmd = ['tee', '-a', logfile]
+ return self._app.runcmd(real_argv, teecmd, **kwargs)
+ else:
+ return self._app.runcmd(real_argv, **kwargs)
except cliapp.AppException as e:
raise cliapp.AppException('In staging area %s: running '
'command \'%s\' failed.' %
--
1.7.10.4
5:57 p.m.
New subject: [PATCH 4/6] Add logfile kwarg to staging area runcmd
On Wed, May 14, 2014 at 01:52:17PM +0100, Richard Ipsum wrote:
try:
- return self._app.runcmd(real_argv, **kwargs)
+ if 'logfile' in kwargs:
+ logfile = kwargs['logfile']
+ del kwargs['logfile']
+
+ if logfile:
+ teecmd = ['tee', '-a', logfile]
+ return self._app.runcmd(real_argv, teecmd, **kwargs)
+ else:
+ return self._app.runcmd(real_argv, **kwargs)
except cliapp.AppException as e:
raise cliapp.AppException('In staging area %s: running '
'command \'%s\' failed.' %
What happens if kwargs does not contain logfile? Looks to me like the
code doesn't run anything at all then.
--
http://www.codethink.co.uk/ http://wiki.baserock.org/ http://www.baserock.com/
6:18 p.m.
New subject: [PATCH 4/6] Add logfile kwarg to staging area runcmd
On Wed, May 14, 2014 at 02:57:28PM +0100, Lars Wirzenius wrote:
On Wed, May 14, 2014 at 01:52:17PM +0100, Richard Ipsum wrote:
> try:
> - return self._app.runcmd(real_argv, **kwargs)
> + if 'logfile' in kwargs:
> + logfile = kwargs['logfile']
> + del kwargs['logfile']
> +
> + if logfile:
> + teecmd = ['tee', '-a', logfile]
> + return self._app.runcmd(real_argv, teecmd, **kwargs)
> + else:
> + return self._app.runcmd(real_argv, **kwargs)
> except cliapp.AppException as e:
> raise cliapp.AppException('In staging area %s: running '
> 'command \'%s\' failed.' %
What happens if kwargs does not contain logfile? Looks to me like the
code doesn't run anything at all then.
Thanks for spotting this, that 'if logfile' block is not supposed to be
indented, raising it one indentation level should fix it.
6:24 p.m.
New subject: [PATCH 4/6] Add logfile kwarg to staging area runcmd
On Wed, May 14, 2014 at 03:18:26PM +0100, Richard Ipsum wrote:
On Wed, May 14, 2014 at 02:57:28PM +0100, Lars Wirzenius wrote:
> On Wed, May 14, 2014 at 01:52:17PM +0100, Richard Ipsum wrote:
> > try:
> > - return self._app.runcmd(real_argv, **kwargs)
> > + if 'logfile' in kwargs:
> > + logfile = kwargs['logfile']
> > + del kwargs['logfile']
> > +
> > + if logfile:
> > + teecmd = ['tee', '-a', logfile]
> > + return self._app.runcmd(real_argv, teecmd, **kwargs)
> > + else:
> > + return self._app.runcmd(real_argv, **kwargs)
> > except cliapp.AppException as e:
> > raise cliapp.AppException('In staging area %s: running '
> > 'command \'%s\' failed.'
%
>
> What happens if kwargs does not contain logfile? Looks to me like the
> code doesn't run anything at all then.
Thanks for spotting this, that 'if logfile' block is not supposed to be
indented, raising it one indentation level should fix it.
Will the variable logfile exist in that case? Would it be simpler to
have this structure:
if 'loglife' in kwargs:
... setup teecmd and call runcmd
else:
... call runcmd without tee
That is, no nesteds ifs?
--
http://www.codethink.co.uk/ http://wiki.baserock.org/ http://www.baserock.com/
6:36 p.m.
New subject: [PATCH 4/6] Add logfile kwarg to staging area runcmd
On Wed, May 14, 2014 at 03:24:20PM +0100, Lars Wirzenius wrote:
On Wed, May 14, 2014 at 03:18:26PM +0100, Richard Ipsum wrote:
> On Wed, May 14, 2014 at 02:57:28PM +0100, Lars Wirzenius wrote:
> > On Wed, May 14, 2014 at 01:52:17PM +0100, Richard Ipsum wrote:
> > > try:
> > > - return self._app.runcmd(real_argv, **kwargs)
> > > + if 'logfile' in kwargs:
> > > + logfile = kwargs['logfile']
> > > + del kwargs['logfile']
> > > +
> > > + if logfile:
> > > + teecmd = ['tee', '-a', logfile]
> > > + return self._app.runcmd(real_argv, teecmd, **kwargs)
> > > + else:
> > > + return self._app.runcmd(real_argv, **kwargs)
> > > except cliapp.AppException as e:
> > > raise cliapp.AppException('In staging area %s: running
'
> > > 'command \'%s\'
failed.' %
> >
> > What happens if kwargs does not contain logfile? Looks to me like the
> > code doesn't run anything at all then.
>
> Thanks for spotting this, that 'if logfile' block is not supposed to be
> indented, raising it one indentation level should fix it.
Will the variable logfile exist in that case? Would it be simpler to
have this structure:
I'd need to set logfile to None as well.
if 'loglife' in kwargs:
... setup teecmd and call runcmd
else:
... call runcmd without tee
That is, no nesteds ifs?
I agree that this is a better way to do it, I'll do it this way.
4:52 p.m.
New subject: [PATCH 5/6] Use logfile kwarg to generate build log
---
morphlib/builder2.py | 71 +++++++++++++++++++++++++++++++++-----------------
1 file changed, 47 insertions(+), 24 deletions(-)
diff --git a/morphlib/builder2.py b/morphlib/builder2.py
index 02e8b48..f896997 100644
--- a/morphlib/builder2.py
+++ b/morphlib/builder2.py
@@ -335,29 +335,41 @@ class ChunkBuilder(BuilderBase):
def build_and_cache(self): # pragma: no cover
with self.build_watch('overall-build'):
- builddir, destdir = \
- self.staging_area.chroot_open(self.artifact.source,
- self.setup_mounts)
- log_name = None
+ builddir, destdir = self.staging_area.chroot_open(
+ self.artifact.source, self.setup_mounts)
+
+ stdout = (self.app.output
+ if self.app.settings['build-log-on-stdout'] else None)
+
+ cache = self.local_artifact_cache
+ logpath = cache.get_source_metadata_filename(
+ self.artifact.source, self.artifact.cache_key, 'build-log')
+
+ _, temppath = tempfile.mkstemp(dir=os.path.dirname(logpath))
+
try:
self.get_sources(builddir)
- with self.local_artifact_cache.put_source_metadata(
- self.artifact.source, self.artifact.cache_key,
- 'build-log') as log:
- log_name = log.real_filename
- self.run_commands(builddir, destdir, log)
- self.create_devices(destdir)
+ self.run_commands(builddir, destdir, temppath, stdout)
+ self.create_devices(destdir)
+
+ os.rename(temppath, logpath)
except BaseException, e:
logging.error('Caught exception: %s' % str(e))
logging.info('Cleaning up staging area')
self.staging_area.chroot_close()
- if log_name:
- with open(log_name) as f:
+ if os.path.isfile(temppath):
+ with open(temppath) as f:
for line in f:
logging.error('OUTPUT FROM FAILED BUILD: %s' %
line.rstrip('\n'))
+
+ os.rename(temppath, logpath)
+ else:
+ logging.error("Couldn't find build log at %s",
temppath)
+
self.staging_area.abort()
raise
+
self.staging_area.chroot_close()
built_artifacts = self.assemble_chunk_artifacts(destdir)
@@ -365,7 +377,8 @@ class ChunkBuilder(BuilderBase):
return built_artifacts
- def run_commands(self, builddir, destdir, logfile): # pragma: no cover
+ def run_commands(self, builddir, destdir,
+ logfilepath, stdout=None): # pragma: no cover
m = self.artifact.source.morphology
bs = morphlib.buildsystem.lookup_build_system(m['build-system'])
@@ -392,8 +405,10 @@ class ChunkBuilder(BuilderBase):
key = '%s-commands' % step
cmds = m.get_commands(key)
if cmds:
- self.app.status(msg='Running %(key)s', key=key)
- logfile.write('# %s\n' % step)
+ with open(logfilepath, 'a') as log:
+ self.app.status(msg='Running %(key)s', key=key)
+ log.write('# %s\n' % step)
+
for cmd in cmds:
if in_parallel:
max_jobs = self.artifact.source.morphology['max-jobs']
@@ -402,23 +417,31 @@ class ChunkBuilder(BuilderBase):
extra_env['MAKEFLAGS'] = '-j%s' % max_jobs
else:
extra_env['MAKEFLAGS'] = '-j1'
+
try:
+ with open(logfilepath, 'a') as log:
+ log.write('# # %s\n' % cmd)
+
# flushing is needed because writes from python and
# writes from being the output in Popen have different
# buffers, but flush handles both
- logfile.write('# # %s\n' % cmd)
- logfile.flush()
+ if stdout:
+ stdout.flush()
+
self.runcmd(['sh', '-c', cmd],
extra_env=extra_env,
cwd=relative_builddir,
- stdout=logfile,
- stderr=subprocess.STDOUT)
- logfile.flush()
+ stdout=stdout or subprocess.PIPE,
+ stderr=subprocess.STDOUT,
+ logfile=logfilepath)
+
+ if stdout:
+ stdout.flush()
except cliapp.AppException, e:
- logfile.flush()
- with open(logfile.name, 'r') as readlog:
- self.app.output.write("%s failed\n" % step)
- shutil.copyfileobj(readlog, self.app.output)
+ 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
def write_system_integration_commands(self, destdir,
--
1.7.10.4
4:52 p.m.
New subject: [PATCH 6/6] Make distbuild put worker logs onto stdout
---
distbuild/worker_build_scheduler.py | 1 +
1 file changed, 1 insertion(+)
diff --git a/distbuild/worker_build_scheduler.py b/distbuild/worker_build_scheduler.py
index 48ef4a7..a61c50f 100644
--- a/distbuild/worker_build_scheduler.py
+++ b/distbuild/worker_build_scheduler.py
@@ -468,6 +468,7 @@ class WorkerConnection(distbuild.StateMachine):
argv = [
self._morph_instance,
'worker-build',
+ '--build-log-on-stdout',
self._job.artifact.name,
]
msg = distbuild.message('exec-request',
--
1.7.10.4
5:17 p.m.
On 14/05/14 13:52, Richard Ipsum wrote:
repo: git://git.baserock.org/baserock/baserock/morph
ref: baserock/richardipsum/build-log-on-stdout-tee
head: ad47e5b8567ece69bda7358f6c8ce4868368c59f
Hi again,
This patch takes care of writing an artifact's build log to both stdout
and a build log file if the --build-log-on-stdout flag is set.
This series uses tee to write the output to a file as well as to stdout.
Using Popen it should be straight forward to send the output to a pipe and
then read that pipe and write to wherever (stdout plus a logfile in our case).
At the moment morph uses cliapp's runcmd rather than Popen. cliapp's runcmd
is a blocking call, so we're not able to read from the pipe until the
command has completed, which prevents real time logging to a number of files.
One solution to this problem might be to spawn a thread which opens a pipe
to the command being executed, the thread then reads from the pipe and writes
to our collection of logfiles, an attempt at this can be found at ref
baserock/richardipsum/build-log-on-stdout3
The test for the getter that was added to the local artifact cache may not
be worth adding: we may want to just use #pragma: no cover
I'd really like this to be in for the Baserock 14.20 release, but that
would require it to be merged within the next couple of hours.
I'll give it a +1 if you can put the reasoning behind the approach into
the commit messages for patches #4 and #5. Otherwise, future developers
will look at this code and go "hmm, I bet this can be done in a neater
way" and then spend two days banging their heads against the various
ways it can almost be implemented, just as you did
Sam
--
Sam Thursfield, Codethink Ltd.
Office telephone: +44 161 236 5575
6:18 p.m.
On Wed, May 14, 2014 at 01:52:13PM +0100, Richard Ipsum wrote:
repo: git://git.baserock.org/baserock/baserock/morph
ref: baserock/richardipsum/build-log-on-stdout-tee
head: ad47e5b8567ece69bda7358f6c8ce4868368c59f
I think I found a bug in the code (see separate message), but other
than that it looks acceptable to me.
--
http://www.codethink.co.uk/ http://wiki.baserock.org/ http://www.baserock.com/
8:31 p.m.
On Wed, May 14, 2014 at 03:18:27PM +0100, Lars Wirzenius wrote:
On Wed, May 14, 2014 at 01:52:13PM +0100, Richard Ipsum wrote:
> repo: git://git.baserock.org/baserock/baserock/morph
> ref: baserock/richardipsum/build-log-on-stdout-tee
> head: ad47e5b8567ece69bda7358f6c8ce4868368c59f
I think I found a bug in the code (see separate message), but other
than that it looks acceptable to me.
The bug you found has been fixed and these changes have been merged, thanks. :)
3242
days inactive
3242
days old
13 comments
3 participants
participants (3)
-
Lars Wirzenius -
Richard Ipsum -
Sam Thursfield