# HG changeset patch # User cmlenz # Date 1120820059 0 # Node ID 01200c88ddb08543bf233c45b3b92c28d3bb0080 # Parent 7129b8a2f12540409dc4f9dcd78cc7077cc45474 Include timing information in the build messages transmitted from slave to master for better accuracy. diff --git a/bitten/master.py b/bitten/master.py --- a/bitten/master.py +++ b/bitten/master.py @@ -18,6 +18,7 @@ # # Author: Christopher Lenz +from itertools import ifilter import logging import os.path import re @@ -70,7 +71,7 @@ platform.id) if not list(builds): logging.info('Enqueuing build of configuration "%s"' - 'at revision [%s] on %s', config.name, + ' at revision [%s] on %s', config.name, rev, platform.name) build = Build(self.env) build.config = config.name @@ -96,13 +97,9 @@ platform = TargetPlatform(self.env, build.platform) logging.debug('Matching slave %s against rules: %s', slave.name, platform.rules) - for property, pattern in platform.rules: - if not property or not pattern: - continue + for property, pattern in ifilter(None, platform.rules): try: - if not re.match(pattern, slave.props.get(property)): - logging.debug('Rule (%s, %s) did not match "%s"', - property, pattern, slave.props.get(property)) + if not re.match(pattern, slave.info.get(property)): matches_platform = False break except re.error, e: @@ -147,7 +144,7 @@ self.env = self.master.env assert self.env self.name = None - self.props = {} + self.info = {} def handle_disconnect(self): if self.name is None: @@ -176,13 +173,13 @@ self.name = elem.attr['name'] for child in elem.children(): if child.name == 'platform': - self.props[Build.MACHINE] = child.gettext() - self.props[Build.PROCESSOR] = child.attr.get('processor') + self.info[Build.MACHINE] = child.gettext() + self.info[Build.PROCESSOR] = child.attr.get('processor') elif child.name == 'os': - self.props[Build.OS_NAME] = child.gettext() - self.props[Build.OS_FAMILY] = child.attr.get('family') - self.props[Build.OS_VERSION] = child.attr.get('version') - self.props[Build.IP_ADDRESS] = self.session.addr[0] + self.info[Build.OS_NAME] = child.gettext() + self.info[Build.OS_FAMILY] = child.attr.get('family') + self.info[Build.OS_VERSION] = child.attr.get('version') + self.info[Build.IP_ADDRESS] = self.session.addr[0] self.name = elem.attr['name'] self.master.slaves[self.name] = self @@ -200,8 +197,9 @@ if msg.get_content_type() == beep.BEEP_XML: elem = xmlio.parse(msg.get_payload()) if elem.name == 'error': - logging.warning('Slave refused build request: %s (%d)', - elem.gettext(), int(elem.attr['code'])) + logging.warning('Slave %s refused build request: ' + '%s (%d)', self.name, elem.gettext(), + int(elem.attr['code'])) return elem = xmlio.parse(msg.get_payload()) @@ -233,16 +231,17 @@ assert msg.get_content_type() == beep.BEEP_XML elem = xmlio.parse(msg.get_payload()) if elem.name == 'error': - logging.warning('Slave did not accept archive: %s (%d)', - elem.gettext(), int(elem.attr['code'])) + logging.warning('Slave %s did not accept archive: %s (%d)', + self.name, elem.gettext(), + int(elem.attr['code'])) if cmd == 'ANS': elem = xmlio.parse(msg.get_payload()) if elem.name == 'started': build.slave = self.name - build.slave_info.update(self.props) - build.started = int(time.time()) + build.slave_info.update(self.info) + build.started = int(_parse_iso_datetime(elem.attr['time'])) build.status = Build.IN_PROGRESS build.update() logging.info('Slave %s started build of "%s" as of [%s]', @@ -254,7 +253,8 @@ step.build = build.id step.name = elem.attr['id'] step.description = elem.attr.get('description') - step.stopped = int(time.time()) + step.started = int(_parse_iso_datetime(elem.attr['time'])) + step.stopped = step.started + int(elem.attr['duration']) step.log = elem.gettext().strip() if elem.attr['result'] == 'failure': logging.warning('Step failed: %s', elem.gettext()) @@ -263,6 +263,15 @@ step.status = BuildStep.SUCCESS step.insert() + elif elem.name == 'completed': + logging.info('Slave %s completed build of "%s" as of [%s]', + self.name, 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 + elif elem.name == 'aborted': logging.info('Slave "%s" aborted build', self.name) build.slave = None @@ -274,25 +283,6 @@ build.update() - elif cmd == 'NUL': - if build.status != Build.PENDING: # Completed - logging.info('Slave %s completed build of "%s" as of [%s]', - self.name, build.config, build.rev) - build.stopped = int(time.time()) - if build.status is Build.IN_PROGRESS: - # Find out whether the build failed or succeeded - build.status = Build.SUCCESS - for step in BuildStep.select(self.env, build=build.id): - if step.status == BuildStep.FAILURE: - build.status = Build.FAILURE - break - - else: # Aborted - build.slave = None - build.started = 0 - - build.update() - # TODO: should not block while reading the file; rather stream it using # asyncore push_with_producer() snapshot_path = self.master.get_snapshot(build, type, encoding) @@ -303,6 +293,22 @@ self.channel.send_msg(message, handle_reply=handle_reply) +def _parse_iso_datetime(string): + """Minimal parser for ISO date-time strings. + + Return the time as floating point number. Only handles UTC timestamps + without time zone information.""" + try: + string = string.split('.', 1)[0] # strip out microseconds + secs = time.mktime(time.strptime(string, '%Y-%m-%dT%H:%M:%S')) + tzoffset = time.timezone + if time.daylight: + tzoffset = time.altzone + return secs - tzoffset + except ValueError, e: + raise ValueError, 'Invalid ISO date/time %s (%s)' % (string, e) + + def main(): from bitten import __version__ as VERSION from optparse import OptionParser diff --git a/bitten/slave.py b/bitten/slave.py --- a/bitten/slave.py +++ b/bitten/slave.py @@ -18,12 +18,12 @@ # # Author: Christopher Lenz +from datetime import datetime import logging import os import platform import sys import tempfile -import time from bitten.build import BuildError from bitten.recipe import Recipe, InvalidRecipeError @@ -134,25 +134,38 @@ try: recipe = Recipe(recipe_path, basedir) - xml = xmlio.Element('started') + xml = xmlio.Element('started', time=datetime.utcnow().isoformat()) self.channel.send_ans(msgno, beep.MIMEMessage(xml)) + failed = False for step in recipe: logging.info('Executing build step "%s"', step.id) + started = datetime.utcnow() try: step.execute(recipe.ctxt) + duration = datetime.utcnow() - started + log = '\n'.join([record[-1] for record in recipe.ctxt._log]) xml = xmlio.Element('step', id=step.id, result='success', - description=step.description)[ - '\n'.join([record[-1] for record in recipe.ctxt._log]) - ] + description=step.description, + time=started.isoformat(), + duration=duration.seconds)[log] recipe.ctxt._log = [] self.channel.send_ans(msgno, beep.MIMEMessage(xml)) except (BuildError, InvalidRecipeError), e: + duration = datetime.utcnow() - started + failed = True xml = xmlio.Element('step', id=step.id, result='failure', - description=step.description)[e] + description=step.description, + time=started.isoformat(), + duration=duration.seconds)[e] self.channel.send_ans(msgno, beep.MIMEMessage(xml)) logging.info('Build completed') + recipe.ctxt._log = [] + xml = xmlio.Element('completed', time=datetime.utcnow().isoformat(), + result=['success', 'failure'][failed]) + self.channel.send_ans(msgno, beep.MIMEMessage(xml)) + self.channel.send_nul(msgno) except InvalidRecipeError, e: diff --git a/bitten/trac_ext/web_ui.py b/bitten/trac_ext/web_ui.py --- a/bitten/trac_ext/web_ui.py +++ b/bitten/trac_ext/web_ui.py @@ -424,6 +424,7 @@ for step in BuildStep.select(self.env, build=build.id): steps.append({ 'name': step.name, 'description': step.description, + 'duration': pretty_timedelta(step.started, step.stopped), 'log': step.log }) hdf['steps'] = steps diff --git a/templates/build.cs b/templates/build.cs --- a/templates/build.cs +++ b/templates/build.cs @@ -157,7 +157,7 @@

Completed: ( ago)
Took:

-

+

()