# HG changeset patch # User cmlenz # Date 1123070074 0 # Node ID 5bf22bb87915df2270729e947e9c01a842a1efe1 # Parent 2a720491d903d62eaa064b3cb5f750e3bf5aa930 Transmit build log and generated data back to the build master in XML format. Closes #23. diff --git a/bitten/build/ctools.py b/bitten/build/ctools.py --- a/bitten/build/ctools.py +++ b/bitten/build/ctools.py @@ -18,22 +18,35 @@ # # Author: Christopher Lenz +import logging + from bitten.build import BuildError +from bitten.util import xmlio from bitten.util.cmdline import Commandline -def make(ctxt, target='all', file=None, jobs=None, keep_going=False): +log = logging.getLogger('bitten.build.ctools') + +def make(ctxt, target=None, file=None, jobs=None, keep_going=False): """Execute a Makefile target.""" - args = ['-C', ctxt.basedir] + args = ['--directory', ctxt.basedir] if file: - args += ['-f', ctxt.resolve(file)] + args += ['--file', ctxt.resolve(file)] if jobs: - args += ['-j', int(jobs)] + args += ['--jobs', int(jobs)] if keep_going: - args.append('-k') - args.append(target) + args.append('--keep-going') + if target: + args.append(target) + + log_elem = xmlio.Element('messages') cmdline = Commandline('make', args) for out, err in cmdline.execute(timeout=100.0): - ctxt.log(ctxt.OUTPUT, out) - ctxt.log(ctxt.ERROR, err) + if out: + log.info(out) + xmlio.SubElement(log_elem, 'message', level='info')[out] + if err: + log.error(err) + xmlio.SubElement(log_elem, 'message', level='error')[err] + ctxt.log(log_elem) if cmdline.returncode != 0: raise BuildError, 'make failed (%s)' % cmdline.returncode diff --git a/bitten/build/pythontools.py b/bitten/build/pythontools.py --- a/bitten/build/pythontools.py +++ b/bitten/build/pythontools.py @@ -18,38 +18,62 @@ # # Author: Christopher Lenz +import logging import re from bitten.build import BuildError +from bitten.util import xmlio from bitten.util.cmdline import Commandline +log = logging.getLogger('bitten.build.pythontools') + def distutils(ctxt, command='build'): """Execute a `distutils` command.""" cmdline = Commandline('python', ['setup.py', command], cwd=ctxt.basedir) + log_elem = xmlio.Element('messages') for out, err in cmdline.execute(timeout=100.0): - ctxt.log(ctxt.OUTPUT, out) - ctxt.log(ctxt.ERROR, err) + if out: + log.info(out) + xmlio.SubElement(log_elem, 'message', level='info')[out] + if err: + level = 'error' + if err.startswith('warning: '): + err = err[9:] + level = 'warning' + log.warning(err) + else: + log.error(err) + xmlio.SubElement(log_elem, 'message', level=level)[err] + ctxt.log(log_elem) if cmdline.returncode != 0: raise BuildError, 'distutils failed (%s)' % cmdline.returncode def pylint(ctxt, file=None): """Extract data from a `pylint` run written to a file.""" assert file, 'Missing required attribute "file"' - _msg_re = re.compile(r'^(?P.+):(?P\d+): ' + msg_re = re.compile(r'^(?P.+):(?P\d+): ' r'\[(?P[A-Z])(?:, (?P[\w\.]+))?\] ' r'(?P.*)$') + msg_types = dict(W='warning', E='error', C='convention', R='refactor') + lint_elem = xmlio.Element('lint') try: fd = open(ctxt.resolve(file), 'r') try: for line in fd: - match = _msg_re.search(line) + match = msg_re.search(line) if match: + type = msg_types.get(match.group('type')) filename = match.group('file') if filename.startswith(ctxt.basedir): filename = filename[len(ctxt.basedir) + 1:] lineno = int(match.group('line')) - # TODO: emit to build master + tag = match.group('tag') + xmlio.SubElement(lint_elem, 'problem', type=type, tag=tag, + file=filename, line=lineno)[ + match.group('msg') or '' + ] + ctxt.report(lint_elem) finally: fd.close() except IOError, e: diff --git a/bitten/master.py b/bitten/master.py --- a/bitten/master.py +++ b/bitten/master.py @@ -31,6 +31,7 @@ from trac.env import Environment from bitten.model import BuildConfig, TargetPlatform, Build, BuildStep +from bitten.store import MetricsStore from bitten.util import archive, beep, xmlio log = logging.getLogger('bitten.master') @@ -38,7 +39,6 @@ DEFAULT_CHECK_INTERVAL = 120 # 2 minutes - class Master(beep.Listener): def __init__(self, env_path, ip, port, @@ -57,12 +57,11 @@ for rev, format, path in snapshots: self.snapshots[(config.name, rev, format)] = path + self._cleanup_orphaned_builds() self.schedule(self.check_interval, self._check_build_triggers) def close(self): - # Remove all pending builds - for build in Build.select(self.env, status=Build.PENDING): - build.delete() + self._cleanup_orphaned_builds() beep.Listener.close(self) def _check_build_triggers(self, when): @@ -114,6 +113,15 @@ slave.send_initiation(build) return + def _cleanup_orphaned_builds(self): + # Remove all pending or in-progress builds + db = self.env.get_db_cnx() + for build in Build.select(self.env, status=Build.IN_PROGRESS, db=db): + build.status = Build.PENDING + build.update(db=db) + for build in Build.select(self.env, status=Build.PENDING, db=db): + build.delete(db=db) + def _cleanup_snapshots(self, when): log.debug('Checking for unused snapshot archives...') for (config, rev, format), path in self.snapshots.items(): @@ -230,8 +238,8 @@ self.channel.send_rpy(msgno, beep.Payload(xml)) def send_initiation(self, build): - log.debug('Initiating build of "%s" on slave %s', build.config, - self.name) + log.info('Initiating build of "%s" on slave %s', build.config, + self.name) def handle_reply(cmd, msgno, ansno, payload): if cmd == 'ERR': @@ -276,58 +284,22 @@ self.name, elem.gettext(), int(elem.attr['code'])) - if cmd == 'ANS': + elif cmd == 'ANS': + assert payload.content_type == beep.BEEP_XML db = self.env.get_db_cnx() elem = xmlio.parse(payload.body) - if elem.name == 'started': - build.slave = self.name - build.slave_info.update(self.info) - build.started = int(_parse_iso_datetime(elem.attr['time'])) - build.status = Build.IN_PROGRESS - log.info('Slave %s started build %d ("%s" as of [%s])', - self.name, build.id, build.config, build.rev) - + self._build_started(db, build, elem) elif elem.name == 'step': - log.info('Slave completed step "%s"', elem.attr['id']) - step = BuildStep(self.env, build=build.id, - name=elem.attr['id'], - description=elem.attr.get('description'), - log=elem.gettext().strip()) - step.started = int(_parse_iso_datetime(elem.attr['time'])) - step.stopped = step.started + int(elem.attr['duration']) - if elem.attr['result'] == 'failure': - log.warning('Step failed: %s', elem.gettext()) - step.status = BuildStep.FAILURE - else: - step.status = BuildStep.SUCCESS - step.insert(db=db) - + self._build_step_completed(db, build, elem) elif elem.name == 'completed': - log.info('Slave %s completed build %d ("%s" as of [%s])', - self.name, build.id, build.config, build.rev) - build.stopped = int(_parse_iso_datetime(elem.attr['time'])) - if elem.attr['result'] == 'failure': - build.status = Build.FAILURE - else: - build.status = Build.SUCCESS - + self._build_completed(db, build, elem) elif elem.name == 'aborted': - log.info('Slave "%s" aborted build %d ("%s" as of [%s])', - self.name, build.id, build.config, build.rev) - build.slave = None - build.started = 0 - build.status = Build.PENDING - build.slave_info = {} - for step in BuildStep.select(self.env, build=build.id, - db=db): - step.delete(db=db) - + self._build_aborted(db, build, elem) elif elem.name == 'error': build.status = Build.FAILURE - build.update(db=db) - db.commit() + db.commit() snapshot_format = { ('application/tar', 'bzip2'): 'bzip2', @@ -342,6 +314,55 @@ content_encoding=encoding) self.channel.send_msg(message, handle_reply=handle_reply) + def _build_started(self, db, build, elem): + build.slave = self.name + build.slave_info.update(self.info) + build.started = int(_parse_iso_datetime(elem.attr['time'])) + build.status = Build.IN_PROGRESS + log.info('Slave %s started build %d ("%s" as of [%s])', + self.name, build.id, build.config, build.rev) + + def _build_step_completed(self, db, build, elem): + log.debug('Slave completed step "%s"', elem.attr['id']) + step = BuildStep(self.env, build=build.id, name=elem.attr['id'], + description=elem.attr.get('description')) + step.started = int(_parse_iso_datetime(elem.attr['time'])) + step.stopped = step.started + int(elem.attr['duration']) + if elem.attr['result'] == 'failure': + log.warning('Step failed: %s', elem.gettext()) + step.status = BuildStep.FAILURE + else: + step.status = BuildStep.SUCCESS + + # TODO: Insert log messages into separate table, and also store reports + log_lines = [] + for log_elem in elem.children('log'): + for messages_elem in log_elem.children('messages'): + for message_elem in messages_elem.children('message'): + log_lines.append(message_elem.gettext()) + step.log = '\n'.join(log_lines) + + step.insert(db=db) + + def _build_completed(self, db, build, elem): + log.info('Slave %s completed build %d ("%s" as of [%s])', self.name, + build.id, build.config, build.rev) + build.stopped = int(_parse_iso_datetime(elem.attr['time'])) + if elem.attr['result'] == 'failure': + build.status = Build.FAILURE + else: + build.status = Build.SUCCESS + + def _build_aborted(self, db, build, elem): + log.info('Slave "%s" aborted build %d ("%s" as of [%s])', + self.name, build.id, build.config, build.rev) + build.slave = None + build.started = 0 + build.status = Build.PENDING + build.slave_info = {} + for step in BuildStep.select(self.env, build=build.id, db=db): + step.delete(db=db) + def _parse_iso_datetime(string): """Minimal parser for ISO date-time strings. diff --git a/bitten/recipe.py b/bitten/recipe.py --- a/bitten/recipe.py +++ b/bitten/recipe.py @@ -37,27 +37,18 @@ class Context(object): """The context in which a recipe command or report is run.""" - ERROR = 0 - OUTPUT = 1 - current_step = None current_function = None def __init__(self, basedir): self.basedir = basedir - self._log = [] + self.output = [] - def log(self, level, text): - if text is None: - return - assert level in (Context.ERROR, Context.OUTPUT), \ - 'Invalid log level %s' % level - if level == Context.ERROR: - log.warning(text) - else: - log.info(text) - self._log.append((self.current_step, self.current_function, level, - time.time(), text)) + def log(self, xml_elem): + self.output.append((Recipe.LOG, self.current_function, xml_elem)) + + def report(self, xml_elem): + self.output.append((Recipe.REPORT, self.current_function, xml_elem)) def resolve(self, *path): return os.path.normpath(os.path.join(self.basedir, *path)) @@ -98,9 +89,10 @@ if self.onerror == 'fail': raise BuildError, e log.warning('Ignoring error in step %s (%s)', self.id, e) - return None finally: ctxt.current_step = None + while ctxt.output: + yield ctxt.output.pop() def _args(self, elem): return dict([(name.replace('-', '_'), value) for name, value @@ -126,6 +118,9 @@ Iterate over this object to get the individual build steps in the order they have been defined in the recipe file.""" + LOG = 'log' + REPORT = 'report' + def __init__(self, filename='recipe.xml', basedir=os.getcwd()): self.ctxt = Context(basedir) fd = file(self.ctxt.resolve(filename), 'r') diff --git a/bitten/slave.py b/bitten/slave.py --- a/bitten/slave.py +++ b/bitten/slave.py @@ -150,15 +150,12 @@ log.info('Executing build step "%s"', step.id) started = datetime.utcnow() try: - step.execute(recipe.ctxt) - duration = datetime.utcnow() - started - output = '\n'.join([record[-1] for record - in recipe.ctxt._log]) xml = xmlio.Element('step', id=step.id, result='success', description=step.description, - time=started.isoformat(), - duration=duration.seconds)[output] - recipe.ctxt._log = [] + time=started.isoformat()) + for type, function, output in step.execute(recipe.ctxt): + xmlio.SubElement(xml, type, type=function)[output] + xml.attr['duration'] = (datetime.utcnow() - started).seconds self.channel.send_ans(msgno, beep.Payload(xml)) except (BuildError, InvalidRecipeError), e: duration = datetime.utcnow() - started @@ -170,7 +167,6 @@ self.channel.send_ans(msgno, beep.Payload(xml)) log.info('Build completed') - recipe.ctxt._log = [] xml = xmlio.Element('completed', time=datetime.utcnow().isoformat(), result=['success', 'failure'][failed]) self.channel.send_ans(msgno, beep.Payload(xml)) diff --git a/bitten/util/xmlio.py b/bitten/util/xmlio.py --- a/bitten/util/xmlio.py +++ b/bitten/util/xmlio.py @@ -76,17 +76,17 @@ >>> print Element('foo')[''] ]]> """ - __slots__ = ['name', 'attrs', 'children'] + __slots__ = ['name', 'attr', 'children'] - def __init__(self, *args, **attrs): + def __init__(self, *args, **attr): """Create an XML element using the specified tag name. The tag name must be supplied as the first positional argument. All keyword arguments following it are handled as attributes of the element. """ self.name = args[0] - self.attrs = dict([(name, value) for name, value in attrs.items() - if value is not None]) + self.attr = dict([(name, value) for name, value in attr.items() + if value is not None]) self.children = [] def __getitem__(self, children): @@ -109,7 +109,7 @@ """ out.write('<') out.write(self.name) - for name, value in self.attrs.items(): + for name, value in self.attr.items(): out.write(' %s="%s"' % (name, self._escape_attr(value))) if self.children: out.write('>') @@ -139,7 +139,7 @@ __slots__ = [] - def __init__(self, *args, **attrs): + def __init__(self, *args, **attr): """Create an XML element using the specified tag name. The first positional argument is the instance of the parent element that @@ -148,7 +148,7 @@ the element. """ assert len(args) == 2 - Element.__init__(self, args[1], **attrs) + Element.__init__(self, args[1], **attr) args[0].children.append(self) diff --git a/recipe.xml b/recipe.xml --- a/recipe.xml +++ b/recipe.xml @@ -8,7 +8,7 @@ + description="Run unit tests and record code coverage"> diff --git a/scripts/build.py b/scripts/build.py --- a/scripts/build.py +++ b/scripts/build.py @@ -43,7 +43,7 @@ log.setLevel(options.loglevel) handler = logging.StreamHandler() handler.setLevel(options.loglevel) - formatter = logging.Formatter('[%(levelname)-8s] %(message)s') + formatter = logging.Formatter('%(message)s') handler.setFormatter(formatter) log.addHandler(handler) @@ -51,9 +51,10 @@ recipe = Recipe() for step in recipe: if not steps_to_run or step.id in steps_to_run: + print print '-->', step.description or step.id - step.execute(recipe.ctxt) - print + for type, function, output in step.execute(recipe.ctxt): + pass if step.id in steps_to_run: steps_to_run[step.id] = True