ostbuild: Save build logs to a file, monitor output for warnings

This is bringing us back closer to metabuild.
This commit is contained in:
Colin Walters 2012-01-16 09:27:46 -05:00
parent 8d36bad691
commit bff6baced8
7 changed files with 342 additions and 315 deletions

View File

@ -30,14 +30,15 @@ pyostbuild_PYTHON = \
src/ostbuild/pyostbuild/builtin_compile_one.py \
src/ostbuild/pyostbuild/builtin_resolve.py \
src/ostbuild/pyostbuild/builtins.py \
src/ostbuild/pyostbuild/filemonitor.py \
src/ostbuild/pyostbuild/__init__.py \
src/ostbuild/pyostbuild/kvfile.py \
src/ostbuild/pyostbuild/main.py \
src/ostbuild/pyostbuild/mainloop.py \
src/ostbuild/pyostbuild/odict.py \
src/ostbuild/pyostbuild/ostbuildlog.py \
src/ostbuild/pyostbuild/ostbuildrc.py \
src/ostbuild/pyostbuild/warningfilter.py \
src/ostbuild/pyostbuild/subprocess_helpers.py \
$(NULL)
bin_SCRIPTS += src/ostbuild/ostbuild-nice-and-log-output

View File

@ -1,280 +0,0 @@
#!/usr/bin/python
#
# Copyright (C) 2011 Colin Walters <walters@verbum.org>
#
# This library is free software; you can redistribute it and/or
# modify it under the terms of the GNU Lesser General Public
# License as published by the Free Software Foundation; either
# version 2 of the License, or (at your option) any later version.
#
# This library is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
# Lesser General Public License for more details.
#
# You should have received a copy of the GNU Lesser General Public
# License along with this library; if not, write to the
# Free Software Foundation, Inc., 59 Temple Place - Suite 330,
# Boston, MA 02111-1307, USA.
import os,sys,subprocess,tempfile,re
import select,time,stat,fcntl
log_name = sys.argv[1]
subprocess_args = sys.argv[2:]
subprocess_nice_args = []
# In the future we should test for this better; possibly implement a
# custom fork handler
try:
chrt_args = ['chrt', '--idle', '0']
proc = subprocess.Popen(chrt_args + ['true'])
if proc.wait() == 0:
subprocess_nice_args.extend(chrt_args)
except OSError, e:
pass
try:
ionice_args = ['ionice', '-c', '3', '-t']
proc = subprocess.Popen(ionice_args + ['true'])
if proc.wait() == 0:
subprocess_nice_args.extend(ionice_args)
except OSError, e:
pass
warning_re = re.compile(r'(: ((warning)|(error)|(fatal error)): )|(make(\[[0-9]+\])?: \*\*\*)')
output_whitelist_re = re.compile(r'^(make(\[[0-9]+\])?: Entering directory)|(ostbuild )')
_bold_sequence = None
_normal_sequence = None
if os.isatty(1):
_bold_sequence = subprocess.Popen(['tput', 'bold'], stdout=subprocess.PIPE, stderr=open('/dev/null', 'w')).communicate()[0]
_normal_sequence = subprocess.Popen(['tput', 'sgr0'], stdout=subprocess.PIPE, stderr=open('/dev/null', 'w')).communicate()[0]
def _bold(text):
if _bold_sequence is not None:
return '%s%s%s' % (_bold_sequence, text, _normal_sequence)
else:
return text
class Mainloop(object):
DEFAULT = None
def __init__(self):
self._running = True
self.poll = select.poll()
self._timeouts = []
self._pid_watches = {}
self._fd_callbacks = {}
@classmethod
def get(cls, context):
if context is None:
if cls.DEFAULT is None:
cls.DEFAULT = cls()
return cls.DEFAULT
raise NotImplementedError("Unknown context %r" % (context, ))
def watch_fd(self, fd, callback):
self.poll.register(fd)
self._fd_callbacks[fd] = callback
def unwatch_fd(self, fd):
self.poll.unregister(fd)
del self._fd_callbacks[fd]
def watch_pid(self, pid, callback):
self._pid_watches[pid] = callback
def timeout_add(self, ms, callback):
self._timeouts.append((ms, callback))
def quit(self):
self._running = False
def run_once(self):
min_timeout = None
if len(self._pid_watches) > 0:
min_timeout = 500
for (ms, callback) in self._timeouts:
if (min_timeout is None) or (ms < min_timeout):
min_timeout = ms
origtime = time.time() * 1000
fds = self.poll.poll(min_timeout)
for fd in fds:
self._fd_callbacks[fd]()
for pid in self._pid_watches:
(opid, status) = os.waitpid(pid, os.WNOHANG)
if opid != 0:
self._pid_watches[pid](opid, status)
del self._pid_watches[pid]
newtime = time.time() * 1000
diff = int(newtime - origtime)
if diff < 0: diff = 0
for i,(ms, callback) in enumerate(self._timeouts):
remaining_ms = ms - diff
if remaining_ms <= 0:
callback()
else:
self._timeouts[i] = (remaining_ms, callback)
def run(self):
while self._running:
self.run_once()
class FileMonitor(object):
def __init__(self):
self._paths = {}
self._path_modtimes = {}
self._timeout = 1000
self._timeout_installed = False
self._loop = Mainloop.get(None)
def _stat(self, path):
try:
st = os.stat(path)
return st[stat.ST_MTIME]
except OSError, e:
return None
def add(self, path, callback):
if path not in self._paths:
self._paths[path] = []
self._path_modtimes[path] = self._stat(path)
self._paths[path].append(callback)
if not self._timeout_installed:
self._timeout_installed = True
self._loop.timeout_add(self._timeout, self._check_files)
def _check_files(self):
for (path,callbacks) in self._paths.iteritems():
mtime = self._stat(path)
orig_mtime = self._path_modtimes[path]
if (mtime is not None) and (orig_mtime is None or (mtime > orig_mtime)):
self._path_modtimes[path] = mtime
for cb in callbacks:
cb()
_filemon = FileMonitor()
class OutputFilter(object):
def __init__(self, filename, output):
self.filename = filename
self.output = output
# inherit globals
self._warning_re = warning_re
self._nonfilter_re = output_whitelist_re
self._buf = ''
self._warning_count = 0
self._filtered_line_count = 0
_filemon.add(filename, self._on_changed)
self._fd = os.open(filename, os.O_RDONLY)
fcntl.fcntl(self._fd, fcntl.F_SETFL, os.O_NONBLOCK)
def _do_read(self):
while True:
buf = os.read(self._fd, 4096)
if buf == '':
break
self._buf += buf
self._flush()
def _write_last_log_lines(self):
_last_line_limit = 100
f = open(logfile_path)
lines = []
for line in f:
if line.startswith('ostbuild '):
continue
lines.append(line)
if len(lines) > _last_line_limit:
lines.pop(0)
f.close()
for line in lines:
self.output.write('| ')
self.output.write(line)
def _flush(self):
while True:
p = self._buf.find('\n')
if p < 0:
break
line = self._buf[0:p]
self._buf = self._buf[p+1:]
match = self._warning_re.search(line)
if match:
self._warning_count += 1
self.output.write(line + '\n')
else:
match = self._nonfilter_re.search(line)
if match:
self.output.write(line + '\n')
else:
self._filtered_line_count += 1
def _on_changed(self):
self._do_read()
def start(self):
self._do_read()
def finish(self, successful):
self._do_read()
if not successful:
self._write_last_log_lines()
pass
self.output.write("ostbuild %s: %d warnings\n" % ('success' if successful else _bold('failed'),
self._warning_count, ))
self.output.write("ostbuild: full log path: %s\n" % (logfile_path, ))
sys.exit(0 if successful else 1)
def _on_subprocess_exit(pid, estatus):
_output_filter.finish(estatus == 0)
if __name__ == '__main__':
user_tmpdir = os.environ.get('XDG_RUNTIME_DIR')
if user_tmpdir is None:
user_tmpdir = os.path.join(os.environ.get('TMPDIR', '/tmp'), 'ostbuild-%s' % (os.getuid(), ))
else:
user_tmpdir = os.path.join(user_tmpdir, 'ostbuild')
if os.path.isdir('_build'):
for filename in os.listdir('_build'):
path = os.path.join('_build', filename)
if filename.startswith('artifact-'):
os.unlink(path)
if not os.path.isdir(user_tmpdir):
os.makedirs(user_tmpdir)
stbuf = os.stat(user_tmpdir)
if stbuf.st_uid != os.getuid():
sys.stderr.write('Directory %s not owned by me!' % (user_tmpdir, ))
sys.exit(1)
logfile_path = os.path.join(user_tmpdir, log_name)
try:
os.unlink(logfile_path)
except OSError, e:
pass
logfile_write_fd = os.open(logfile_path, os.O_WRONLY | os.O_CREAT | os.O_EXCL)
global _logfile_f
_logfile_f = os.fdopen(logfile_write_fd, "w")
sys.stdout.write('ostbuild: logging to %r\n' % (logfile_path, ))
sys.stdout.flush()
global _output_filter
_output_filter = OutputFilter(logfile_path, sys.stdout)
_output_filter.start()
args = list(subprocess_nice_args)
args.extend(subprocess_args)
devnull=open('/dev/null')
_logfile_f.write("%s: running: %r\n" % (sys.argv[0], args, ))
_logfile_f.flush()
proc = subprocess.Popen(args, stdin=devnull, stdout=logfile_write_fd, stderr=logfile_write_fd)
global _loop
_loop = Mainloop.get(None)
_loop.watch_pid(proc.pid, _on_subprocess_exit)
_loop.run()

View File

@ -17,12 +17,14 @@
import os,sys,subprocess,tempfile,re,shutil
import argparse
import time
import json
from StringIO import StringIO
from . import builtins
from .ostbuildlog import log, fatal
from .subprocess_helpers import run_sync, run_sync_get_output
from .subprocess_helpers import run_sync_monitor_log_file
from . import ostbuildrc
from . import buildutil
from . import kvfile
@ -38,17 +40,6 @@ class OstbuildBuild(builtins.Builtin):
def __init__(self):
builtins.Builtin.__init__(self)
def _ensure_vcs_mirror(self, name, keytype, uri, branch):
assert keytype == 'git'
mirror = os.path.join(self.mirrordir, name)
tmp_mirror = mirror + '.tmp'
if os.path.isdir(tmp_mirror):
shutil.rmtree(tmp_mirror)
if not os.path.isdir(mirror):
run_sync(['git', 'clone', '--mirror', uri, tmp_mirror])
os.rename(tmp_mirror, mirror)
return mirror
def _get_vcs_checkout(self, name, keytype, mirrordir, branch):
checkoutdir = os.path.join(self.workdir, 'src')
if not os.path.isdir(checkoutdir):
@ -218,9 +209,23 @@ class OstbuildBuild(builtins.Builtin):
shutil.rmtree(component_resultdir)
os.makedirs(component_resultdir)
logdir = os.path.join(self.workdir, 'logs', 'compile', name)
old_logdir = os.path.join(self.workdir, 'old-logs', 'compile', name)
if not os.path.isdir(logdir):
os.makedirs(logdir)
if not os.path.isdir(old_logdir):
os.makedirs(old_logdir)
log_path = os.path.join(logdir, '%s.log' % (name, ))
if os.path.isfile(log_path):
curtime = int(time.time())
saved_name = '%s-%d.log' % (name, int(time.time()),)
os.rename(log_path, os.path.join(old_logdir, saved_name))
if self.args.debug_shell:
self._launch_debug_shell(architecture, buildroot_name, cwd=component_src)
else:
log("Logging to %s" % (log_path, ))
f = open(log_path, 'w')
chroot_args = self._get_ostbuild_chroot_args(architecture)
chroot_args.extend(['--buildroot=' + buildroot_name,
'--workdir=' + self.workdir,
@ -233,11 +238,11 @@ class OstbuildBuild(builtins.Builtin):
if component_config_opts is not None:
chroot_args.extend(component_config_opts)
if self.buildopts.shell_on_failure:
ecode = run_sync(chroot_args, cwd=component_src, fatal_on_error=False)
ecode = run_sync_monitor_log_file(chroot_args, log_path, cwd=component_src, fatal_on_error=False)
if ecode != 0:
self._launch_debug_shell(architecture, buildroot_name, cwd=component_src)
else:
run_sync(chroot_args, cwd=component_src, fatal_on_error=True)
run_sync_monitor_log_file(chroot_args, log_path, cwd=component_src)
run_sync(['ostree', '--repo=' + self.repo,
'commit', '-b', buildname, '-s', 'Build ' + artifact_meta['version'],

View File

@ -0,0 +1,64 @@
#
# Copyright (C) 2011 Colin Walters <walters@verbum.org>
#
# This library is free software; you can redistribute it and/or
# modify it under the terms of the GNU Lesser General Public
# License as published by the Free Software Foundation; either
# version 2 of the License, or (at your option) any later version.
#
# This library is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
# Lesser General Public License for more details.
#
# You should have received a copy of the GNU Lesser General Public
# License along with this library; if not, write to the
# Free Software Foundation, Inc., 59 Temple Place - Suite 330,
# Boston, MA 02111-1307, USA.
import os
import stat
from . import mainloop
_global_filemon = None
class FileMonitor(object):
def __init__(self):
self._paths = {}
self._path_modtimes = {}
self._timeout = 1000
self._timeout_installed = False
self._loop = mainloop.Mainloop.get(None)
@classmethod
def get(cls):
global _global_filemon
if _global_filemon is None:
_global_filemon = cls()
return _global_filemon
def _stat(self, path):
try:
st = os.stat(path)
return st[stat.ST_MTIME]
except OSError, e:
return None
def add(self, path, callback):
if path not in self._paths:
self._paths[path] = []
self._path_modtimes[path] = self._stat(path)
self._paths[path].append(callback)
if not self._timeout_installed:
self._timeout_installed = True
self._loop.timeout_add(self._timeout, self._check_files)
def _check_files(self):
for (path,callbacks) in self._paths.iteritems():
mtime = self._stat(path)
orig_mtime = self._path_modtimes[path]
if (mtime is not None) and (orig_mtime is None or (mtime > orig_mtime)):
self._path_modtimes[path] = mtime
for cb in callbacks:
cb()

View File

@ -0,0 +1,89 @@
#
# Copyright (C) 2011 Colin Walters <walters@verbum.org>
#
# This library is free software; you can redistribute it and/or
# modify it under the terms of the GNU Lesser General Public
# License as published by the Free Software Foundation; either
# version 2 of the License, or (at your option) any later version.
#
# This library is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
# Lesser General Public License for more details.
#
# You should have received a copy of the GNU Lesser General Public
# License along with this library; if not, write to the
# Free Software Foundation, Inc., 59 Temple Place - Suite 330,
# Boston, MA 02111-1307, USA.
import os
import sys
import select
import time
class Mainloop(object):
DEFAULT = None
def __init__(self):
self._running = True
self.poll = select.poll()
self._timeouts = []
self._pid_watches = {}
self._fd_callbacks = {}
@classmethod
def get(cls, context):
if context is None:
if cls.DEFAULT is None:
cls.DEFAULT = cls()
return cls.DEFAULT
raise NotImplementedError("Unknown context %r" % (context, ))
def watch_fd(self, fd, callback):
self.poll.register(fd)
self._fd_callbacks[fd] = callback
def unwatch_fd(self, fd):
self.poll.unregister(fd)
del self._fd_callbacks[fd]
def watch_pid(self, pid, callback):
self._pid_watches[pid] = callback
def timeout_add(self, ms, callback):
self._timeouts.append((ms, callback))
def quit(self):
self._running = False
def run_once(self):
min_timeout = None
if len(self._pid_watches) > 0:
min_timeout = 500
for (ms, callback) in self._timeouts:
if (min_timeout is None) or (ms < min_timeout):
min_timeout = ms
origtime = time.time() * 1000
fds = self.poll.poll(min_timeout)
for fd in fds:
self._fd_callbacks[fd]()
to_delete_pids = []
for pid in self._pid_watches:
(opid, status) = os.waitpid(pid, os.WNOHANG)
if opid != 0:
to_delete_pids.append(pid)
self._pid_watches[pid](opid, status)
for pid in to_delete_pids:
del self._pid_watches[pid]
newtime = time.time() * 1000
diff = int(newtime - origtime)
if diff < 0: diff = 0
for i,(ms, callback) in enumerate(self._timeouts):
remaining_ms = ms - diff
if remaining_ms <= 0:
callback()
else:
self._timeouts[i] = (remaining_ms, callback)
def run(self):
while self._running:
self.run_once()

View File

@ -22,6 +22,8 @@ import sys
import subprocess
from .ostbuildlog import log, fatal
from .warningfilter import WarningFilter
from .mainloop import Mainloop
def _get_env_for_cwd(cwd=None, env=None):
# This dance is necessary because we want to keep the PWD
@ -40,7 +42,7 @@ def _get_env_for_cwd(cwd=None, env=None):
env_copy = env
return env_copy
def run_sync_get_output(args, cwd=None, env=None, stderr=None, none_on_error=False,
def run_sync_get_output(args, cwd=None, env=None, stdout=None, stderr=None, none_on_error=False,
log_success=False, log_initiation=False):
if log_initiation:
log("running: %s" % (subprocess.list2cmdline(args),))
@ -67,31 +69,32 @@ def run_sync_get_output(args, cwd=None, env=None, stderr=None, none_on_error=Fal
return None
def run_sync(args, cwd=None, env=None, fatal_on_error=True, keep_stdin=False,
log_success=True, log_initiation=True):
log_success=True, log_initiation=True, stdout=None,
stderr=None):
if log_initiation:
log("running: %s" % (subprocess.list2cmdline(args),))
# This dance is necessary because we want to keep the PWD
# environment variable up to date. Not doing so is a recipie
# for triggering edge conditions in pwd lookup.
if (cwd is not None) and (env is None or ('PWD' in env)):
if env is None:
env_copy = os.environ.copy()
else:
env_copy = env.copy()
if ('PWD' in env_copy) and (not cwd.startswith('/')):
env_copy['PWD'] = os.path.join(env_copy['PWD'], cwd)
else:
env_copy['PWD'] = cwd
else:
env_copy = env
env_copy = _get_env_for_cwd(cwd, env)
if keep_stdin:
target_stdin = sys.stdin
stdin_target = sys.stdin
else:
target_stdin = open('/dev/null', 'r')
proc = subprocess.Popen(args, stdin=target_stdin, stdout=sys.stdout, stderr=sys.stderr,
stdin_target = open('/dev/null', 'r')
if stdout is None:
stdout_target = sys.stdout
else:
stdout_target = stdout
if stderr is None:
stderr_target = sys.stderr
else:
stderr_target = stderr
proc = subprocess.Popen(args, stdin=stdin_target, stdout=stdout_target, stderr=stderr_target,
close_fds=True, cwd=cwd, env=env_copy)
if not keep_stdin:
target_stdin.close()
stdin_target.close()
returncode = proc.wait()
if fatal_on_error and returncode != 0:
logfn = fatal
@ -102,3 +105,35 @@ def run_sync(args, cwd=None, env=None, fatal_on_error=True, keep_stdin=False,
if logfn is not None:
logfn("pid %d exited with code %d" % (proc.pid, returncode))
return returncode
def run_sync_monitor_log_file(args, logfile, cwd=None, env=None,
fatal_on_error=True, log_initiation=True):
if log_initiation:
log("running: %s" % (subprocess.list2cmdline(args),))
env_copy = _get_env_for_cwd(cwd, env)
logfile_f = open(logfile, 'w')
proc = subprocess.Popen(args, stdin=open('/dev/null', 'r'),
stdout=logfile_f,
stderr=subprocess.STDOUT,
close_fds=True, cwd=cwd, env=env_copy)
warnfilter = WarningFilter(logfile, sys.stdout)
warnfilter.start()
loop = Mainloop.get(None)
def _on_pid_exited(pid, estatus):
failed = estatus != 0
warnfilter.finish(not failed)
if fatal_on_error and failed:
logfn = fatal
else:
logfn = log
log("pid %d exited with code %d" % (pid, estatus))
loop.quit()
loop.watch_pid(proc.pid, _on_pid_exited)
loop.run()
return proc.returncode

View File

@ -0,0 +1,113 @@
#
# Copyright (C) 2011 Colin Walters <walters@verbum.org>
#
# This library is free software; you can redistribute it and/or
# modify it under the terms of the GNU Lesser General Public
# License as published by the Free Software Foundation; either
# version 2 of the License, or (at your option) any later version.
#
# This library is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
# Lesser General Public License for more details.
#
# You should have received a copy of the GNU Lesser General Public
# License along with this library; if not, write to the
# Free Software Foundation, Inc., 59 Temple Place - Suite 330,
# Boston, MA 02111-1307, USA.
import os
import re
import stat
import fcntl
import subprocess
from . import filemonitor
from . import mainloop
warning_re = re.compile(r'(: ((warning)|(error)|(fatal error)): )|(make(\[[0-9]+\])?: \*\*\*)')
output_whitelist_re = re.compile(r'^(make(\[[0-9]+\])?: Entering directory)|(ostbuild )')
_bold_sequence = None
_normal_sequence = None
if os.isatty(1):
_bold_sequence = subprocess.Popen(['tput', 'bold'], stdout=subprocess.PIPE, stderr=open('/dev/null', 'w')).communicate()[0]
_normal_sequence = subprocess.Popen(['tput', 'sgr0'], stdout=subprocess.PIPE, stderr=open('/dev/null', 'w')).communicate()[0]
def _bold(text):
if _bold_sequence is not None:
return '%s%s%s' % (_bold_sequence, text, _normal_sequence)
else:
return text
class WarningFilter(object):
def __init__(self, filename, output):
self.filename = filename
self.output = output
# inherit globals
self._warning_re = warning_re
self._nonfilter_re = output_whitelist_re
self._buf = ''
self._warning_count = 0
self._filtered_line_count = 0
filemon = filemonitor.FileMonitor.get()
filemon.add(filename, self._on_changed)
self._fd = os.open(filename, os.O_RDONLY)
fcntl.fcntl(self._fd, fcntl.F_SETFL, os.O_NONBLOCK)
def _do_read(self):
while True:
buf = os.read(self._fd, 4096)
if buf == '':
break
self._buf += buf
self._flush()
def _write_last_log_lines(self):
_last_line_limit = 100
f = open(self.filename)
lines = []
for line in f:
if line.startswith('ostbuild '):
continue
lines.append(line)
if len(lines) > _last_line_limit:
lines.pop(0)
f.close()
for line in lines:
self.output.write('| ')
self.output.write(line)
def _flush(self):
while True:
p = self._buf.find('\n')
if p < 0:
break
line = self._buf[0:p]
self._buf = self._buf[p+1:]
match = self._warning_re.search(line)
if match:
self._warning_count += 1
self.output.write(line + '\n')
else:
match = self._nonfilter_re.search(line)
if match:
self.output.write(line + '\n')
else:
self._filtered_line_count += 1
def _on_changed(self):
self._do_read()
def start(self):
self._do_read()
def finish(self, successful):
self._do_read()
if not successful:
self._write_last_log_lines()
pass
self.output.write("ostbuild %s: %d warnings\n" % ('success' if successful else _bold('failed'),
self._warning_count, ))
self.output.write("ostbuild: full log path: %s\n" % (self.filename, ))