Mercurial > bitten > bitten-test
changeset 93:b289e572bc7e
Improved logging; the build master can now optionally log to a file. Closes #13.
| author | cmlenz |
|---|---|
| date | Fri, 15 Jul 2005 13:59:54 +0000 |
| parents | 2e090827c63a |
| children | e5d1a792aa45 |
| files | bitten/master.py bitten/recipe.py bitten/slave.py bitten/util/beep.py bitten/util/cmdline.py |
| diffstat | 5 files changed, 129 insertions(+), 91 deletions(-) [+] |
line wrap: on
line diff
--- a/bitten/master.py +++ b/bitten/master.py @@ -32,6 +32,8 @@ from bitten.model import BuildConfig, TargetPlatform, Build, BuildStep from bitten.util import archive, beep, xmlio +log = logging.getLogger('bitten.master') + class Master(beep.Listener): @@ -67,8 +69,8 @@ repos.sync() for config in BuildConfig.select(self.env): - logging.debug('Checking for changes to "%s" at %s', - config.label, config.path) + log.debug('Checking for changes to "%s" at %s', config.label, + config.path) node = repos.get_node(config.path) for path, rev, chg in node.get_history(): enqueued = False @@ -78,9 +80,9 @@ builds = Build.select(self.env, config.name, rev, platform.id) if not list(builds): - logging.info('Enqueuing build of configuration "%s"' - ' at revision [%s] on %s', config.name, - rev, platform.name) + log.info('Enqueuing build of configuration "%s"at ' + 'revision [%s] on %s', config.name, rev, + platform.name) build = Build(self.env) build.config = config.name build.rev = str(rev) @@ -99,7 +101,7 @@ def _check_build_queue(self, when): if not self.slaves: return - logging.debug('Checking for pending builds...') + log.debug('Checking for pending builds...') for build in Build.select(self.env, status=Build.PENDING): for slave in self.slaves.get(build.platform, []): active_builds = Build.select(self.env, slave=slave.name, @@ -109,7 +111,7 @@ return def _cleanup_snapshots(self, when): - logging.debug('Checking for unused snapshot archives...') + log.debug('Checking for unused snapshot archives...') for (config, rev, format), path in self.snapshots.items(): keep = False for build in Build.select(self.env, config=config, rev=rev): @@ -117,7 +119,7 @@ keep = True break if not keep: - logging.info('Removing unused snapshot %s', path) + log.info('Removing unused snapshot %s', path) os.unlink(path) del self.snapshots[(config, rev, format)] @@ -127,7 +129,7 @@ config = BuildConfig(self.env, build.config) snapshot = archive.pack(self.env, path=config.path, rev=build.rev, prefix=config.name, format=format) - logging.info('Prepared snapshot archive at %s' % snapshot) + log.info('Prepared snapshot archive at %s' % snapshot) self.snapshots[(build.config, build.rev, format)] = snapshot return snapshot @@ -144,22 +146,22 @@ match = False break except re.error, e: - logging.error('Invalid platform matching pattern "%s"', - pattern, exc_info=True) + log.error('Invalid platform matching pattern "%s"', + pattern, exc_info=True) match = False break if match: - logging.info('Slave %s matched target platform %s', - handler.name, platform.name) + log.info('Slave %s matched target platform %s', + handler.name, platform.name) self.slaves[platform.id].add(handler) any_match = True if not any_match: - logging.warning('Slave %s does not match any of the configured ' - 'target platforms', handler.name) + log.warning('Slave %s does not match any of the configured target ' + 'platforms', handler.name) return False - logging.info('Registered slave "%s"', handler.name) + log.info('Registered slave "%s"', handler.name) return True def unregister(self, handler): @@ -168,14 +170,14 @@ for build in Build.select(self.env, slave=handler.name, status=Build.IN_PROGRESS): - logging.info('Build [%s] of "%s" by %s cancelled', build.rev, - build.config, handler.name) + log.info('Build [%s] of "%s" by %s cancelled', build.rev, + build.config, handler.name) build.slave = None build.status = Build.PENDING build.started = 0 build.update() break - logging.info('Unregistered slave "%s"', handler.name) + log.info('Unregistered slave "%s"', handler.name) class OrchestrationProfileHandler(beep.ProfileHandler): @@ -222,17 +224,17 @@ self.channel.send_rpy(msgno, beep.Payload(xml)) def send_initiation(self, build): - logging.debug('Initiating build of "%s" on slave %s', build.config, - self.name) + log.debug('Initiating build of "%s" on slave %s', build.config, + self.name) def handle_reply(cmd, msgno, ansno, payload): if cmd == 'ERR': if payload.content_type == beep.BEEP_XML: elem = xmlio.parse(payload.body) if elem.name == 'error': - logging.warning('Slave %s refused build request: ' - '%s (%d)', self.name, elem.gettext(), - int(elem.attr['code'])) + log.warning('Slave %s refused build request: %s (%d)', + self.name, elem.gettext(), + int(elem.attr['code'])) return elem = xmlio.parse(payload.body) @@ -264,9 +266,9 @@ assert payload.content_type == beep.BEEP_XML elem = xmlio.parse(payload.body) if elem.name == 'error': - logging.warning('Slave %s did not accept archive: %s (%d)', - self.name, elem.gettext(), - int(elem.attr['code'])) + log.warning('Slave %s did not accept archive: %s (%d)', + self.name, elem.gettext(), + int(elem.attr['code'])) if cmd == 'ANS': elem = xmlio.parse(payload.body) @@ -277,11 +279,11 @@ 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]', - self.name, build.config, build.rev) + log.info('Slave %s started build of "%s" as of [%s]', + self.name, build.config, build.rev) elif elem.name == 'step': - logging.info('Slave completed step "%s"', elem.attr['id']) + log.info('Slave completed step "%s"', elem.attr['id']) step = BuildStep(self.env) step.build = build.id step.name = elem.attr['id'] @@ -290,15 +292,15 @@ 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()) + log.warning('Step failed: %s', elem.gettext()) step.status = BuildStep.FAILURE else: 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) + log.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 @@ -306,7 +308,7 @@ build.status = Build.SUCCESS elif elem.name == 'aborted': - logging.info('Slave "%s" aborted build', self.name) + log.info('Slave "%s" aborted build %d', self.name, build.id) build.slave = None build.started = 0 build.status = Build.PENDING @@ -355,7 +357,10 @@ parser.add_option('-p', '--port', action='store', type='int', dest='port', help='port number to use') parser.add_option('-H', '--host', action='store', dest='host', + metavar='HOSTNAME', help='the host name or IP address to bind to') + parser.add_option('-l', '--log', dest='logfile', metavar='FILENAME', + help='write log messages to FILENAME') parser.add_option('--debug', action='store_const', dest='loglevel', const=logging.DEBUG, help='enable debugging output') parser.add_option('-v', '--verbose', action='store_const', dest='loglevel', @@ -364,12 +369,30 @@ const=logging.ERROR, help='print as little as possible') parser.set_defaults(port=7633, loglevel=logging.WARNING) options, args = parser.parse_args() - + if len(args) < 1: parser.error('incorrect number of arguments') env_path = args[0] - logging.getLogger().setLevel(options.loglevel) + # Configure logging + log = logging.getLogger('bitten') + log.setLevel(options.loglevel) + handler = logging.StreamHandler() + if options.logfile: + handler.setLevel(logging.WARNING) + else: + handler.setLevel(options.loglevel) + formatter = logging.Formatter('%(message)s') + handler.setFormatter(formatter) + log.addHandler(handler) + if options.logfile: + handler = logging.FileHandler(options.logfile) + handler.setLevel(options.loglevel) + formatter = logging.Formatter('%(asctime)s [%(name)s] %(levelname)s: ' + '%(message)s') + handler.setFormatter(formatter) + log.addHandler(handler) + port = options.port if not (1 <= port <= 65535): parser.error('port must be an integer in the range 1-65535') @@ -381,7 +404,7 @@ try: host = socket.gethostbyaddr(ip)[0] except socket.error, e: - logging.warning('Reverse host name lookup failed (%s)', e) + log.warning('Reverse host name lookup failed (%s)', e) host = ip master = Master(env_path, host, port)
--- a/bitten/recipe.py +++ b/bitten/recipe.py @@ -27,6 +27,8 @@ __all__ = ['Recipe'] +log = logging.getLogger('bitten.recipe') + class InvalidRecipeError(Exception): """Exception raised when a recipe cannot be processed.""" @@ -51,9 +53,9 @@ assert level in (Context.ERROR, Context.OUTPUT), \ 'Invalid log level %s' % level if level == Context.ERROR: - logging.warning(text) + log.warning(text) else: - logging.info(text) + log.info(text) self._log.append((self.current_step, self.current_function, level, time.time(), text)) @@ -95,7 +97,7 @@ except BuildError, e: if self.onerror == 'fail': raise BuildError, e - logging.warning('Ignoring error in step %s (%s)', self.id, e) + log.warning('Ignoring error in step %s (%s)', self.id, e) return None finally: ctxt.current_step = None
--- a/bitten/slave.py +++ b/bitten/slave.py @@ -30,6 +30,8 @@ from bitten.recipe import Recipe, InvalidRecipeError from bitten.util import archive, beep, xmlio +log = logging.getLogger('bitten.slave') + class Slave(beep.Initiator): """Build slave.""" @@ -41,7 +43,7 @@ def greeting_received(self, profiles): if OrchestrationProfileHandler.URI not in profiles: err = 'Peer does not support the Bitten orchestration profile' - logging.error(err) + log.error(err) raise beep.TerminateSession, err self.channels[0].profile.send_start([OrchestrationProfileHandler]) @@ -61,17 +63,17 @@ if payload.content_type == beep.BEEP_XML: elem = xmlio.parse(payload.body) if elem.name == 'error': - logging.error('Slave registration failed: %s (%d)', - elem.gettext(), int(elem.attr['code'])) + log.error('Slave registration failed: %s (%d)', + elem.gettext(), int(elem.attr['code'])) raise beep.TerminateSession, 'Registration failed!' - logging.info('Registration successful') + log.info('Registration successful') system, node, release, version, machine, processor = platform.uname() system, release, version = platform.system_alias(system, release, version) if self.session.name is not None: node = self.session.name - logging.info('Registering with build master as %s', node) + log.info('Registering with build master as %s', node) xml = xmlio.Element('register', name=node)[ xmlio.Element('platform', processor=processor)[machine], xmlio.Element('os', family=os.name, version=release)[system] @@ -117,12 +119,12 @@ finally: archive_file.close() - logging.debug('Received snapshot archive: %s', archive_path) + log.debug('Received snapshot archive: %s', archive_path) # Unpack the archive prefix = archive.unpack(archive_path, workdir) path = os.path.join(workdir, prefix) - logging.debug('Unpacked snapshot to %s' % path) + log.debug('Unpacked snapshot to %s' % path) # Fix permissions for root, dirs, files in os.walk(workdir, topdown=False): @@ -134,8 +136,9 @@ self.execute_build(msgno, path, self.recipe_path) def execute_build(self, msgno, basedir, recipe_path): - logging.info('Building in directory %s using recipe %s', basedir, - recipe_path) + global log + log.info('Building in directory %s using recipe %s', basedir, + recipe_path) try: recipe = Recipe(recipe_path, basedir) @@ -144,16 +147,17 @@ failed = False for step in recipe: - logging.info('Executing build step "%s"', step.id) + log.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]) + 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)[log] + duration=duration.seconds)[output] recipe.ctxt._log = [] self.channel.send_ans(msgno, beep.Payload(xml)) except (BuildError, InvalidRecipeError), e: @@ -165,7 +169,7 @@ duration=duration.seconds)[e] self.channel.send_ans(msgno, beep.Payload(xml)) - logging.info('Build completed') + log.info('Build completed') recipe.ctxt._log = [] xml = xmlio.Element('completed', time=datetime.utcnow().isoformat(), result=['success', 'failure'][failed]) @@ -215,7 +219,13 @@ else: port = 7633 - logging.getLogger().setLevel(options.loglevel) + log = logging.getLogger('bitten') + log.setLevel(options.loglevel) + handler = logging.StreamHandler() + handler.setLevel(options.loglevel) + formatter = logging.Formatter('[%(levelname)-8s] %(message)s') + handler.setFormatter(formatter) + log.addHandler(handler) slave = Slave(host, port, options.name) try:
--- a/bitten/util/beep.py +++ b/bitten/util/beep.py @@ -51,6 +51,8 @@ BEEP_XML = 'application/beep+xml' +log = logging.getLogger('bitten.beep') + class ProtocolError(Exception): """Generic root class for BEEP exceptions.""" @@ -75,7 +77,7 @@ self.sessions = [] self.profiles = {} # Mapping from URIs to ProfileHandler sub-classes self.eventqueue = [] - logging.debug('Listening to connections on %s:%d', ip, port) + log.debug('Listening to connections on %s:%d', ip, port) self.listen(5) def writable(self): @@ -93,7 +95,7 @@ def handle_accept(self): """Start a new BEEP session initiated by a peer.""" conn, (ip, port) = self.accept() - logging.debug('Connected to %s:%d', ip, port) + log.debug('Connected to %s:%d', ip, port) self.sessions.append(Session(self, conn, (ip, port), self.profiles, first_channelno=2)) @@ -142,8 +144,8 @@ else: self.close() def handle_error(channelno, code, message): - logging.error('Failed to close channel %d', channelno) - logging.debug('Closing session with %s', session.addr) + log.error('Failed to close channel %d', channelno) + log.debug('Closing session with %s', session.addr) session.terminate(handle_ok=handle_ok) self.schedule(0, terminate_next_session) self.run(.5) @@ -180,15 +182,14 @@ def close(self): if self.listener: - logging.debug('Closing connection to %s:%s', self.addr[0], - self.addr[1]) + log.debug('Closing connection to %s:%s', self.addr[0], self.addr[1]) self.listener.sessions.remove(self) else: - logging.info('Session terminated') + log.info('Session terminated') asynchat.async_chat.close(self) def handle_close(self): - logging.warning('Peer %s:%s closed connection' % self.addr) + log.warning('Peer %s:%s closed connection' % self.addr) channels = self.channels.keys() channels.reverse() for channelno in channels: @@ -200,7 +201,7 @@ cls, value = sys.exc_info()[:2] if cls is TerminateSession: raise cls, value - logging.exception(value) + log.exception(value) self.close() def collect_incoming_data(self, data): @@ -231,8 +232,8 @@ except ValueError: # TODO: Malformed frame... should we terminate the session # here? - logging.error('Malformed frame header: [%s]', - ' '.join(self.header)) + log.error('Malformed frame header: [%s]', + ' '.join(self.header)) self.header = None return if size == 0: @@ -259,7 +260,7 @@ This parses the frame header and decides which channel to pass it to. """ - logging.debug('Handling frame [%s]', ' '.join(header)) + log.debug('Handling frame [%s]', ' '.join(header)) msgno = None channel = None try: @@ -279,7 +280,7 @@ self.channels[channel].handle_data_frame(cmd, msgno, more, seqno, ansno, payload) except (ValueError, TypeError, ProtocolError), e: - logging.exception(e) + log.exception(e) if channel == 0 and msgno is not None: self.channels[0].profile.send_error(msgno, 550, e) @@ -294,8 +295,8 @@ else: close_next_channel() def _handle_error(code, message): - logging.error('Peer refused to close channel %d: %s (%d)', - channelno, message, code) + log.error('Peer refused to close channel %d: %s (%d)', + channelno, message, code) if handle_error is not None: handle_error(channelno, code, message) else: @@ -320,13 +321,13 @@ """ Session.__init__(self, profiles=profiles or {}) self.create_socket(socket.AF_INET, socket.SOCK_STREAM) - logging.debug('Connecting to %s:%s', ip, port) + log.debug('Connecting to %s:%s', ip, port) self.addr = (ip, port) self.connect(self.addr) def handle_connect(self): """Called by asyncore when the connection is established.""" - logging.debug('Connected to peer at %s:%s', self.addr[0], self.addr[1]) + log.debug('Connected to peer at %s:%s', self.addr[0], self.addr[1]) def greeting_received(self, profiles): """Sub-classes should override this to start the channels they need. @@ -343,7 +344,7 @@ try: asyncore.loop() except TerminateSession, e: - logging.info('Terminating session') + log.info('Terminating session') self.terminate() def quit(self): @@ -546,7 +547,7 @@ assert self.ansno is not None headerbits.append(self.ansno) header = ' '.join([str(bit) for bit in headerbits]) - logging.debug('Sending frame [%s]', header) + log.debug('Sending frame [%s]', header) frame = '\r\n'.join((header, data, 'END', '')) self.channel.seqno[1] += len(data) @@ -599,7 +600,7 @@ def handle_connect(self): """Send a greeting reply directly after connecting to the peer.""" profile_uris = self.session.profiles.keys() - logging.debug('Send greeting with profiles: %s', profile_uris) + log.debug('Send greeting with profiles: %s', profile_uris) xml = xmlio.Element('greeting')[ [xmlio.Element('profile', uri=uri) for uri in profile_uris] ] @@ -617,8 +618,8 @@ return for profile in elem.children('profile'): if profile.attr['uri'] in self.session.profiles: - logging.debug('Start channel %s for profile <%s>', - elem.attr['number'], profile.attr['uri']) + log.debug('Start channel %s for profile <%s>', + elem.attr['number'], profile.attr['uri']) channel = Channel(self.session, channelno, self.session.profiles[profile.attr['uri']]) self.session.channels[channelno] = channel @@ -666,15 +667,15 @@ assert message.content_type == BEEP_XML elem = xmlio.parse(message.body) assert elem.name == 'error' - logging.warning('Received error in response to message #%d: %s (%d)', - msgno, elem.gettext(), int(elem.attr['code'])) + log.warning('Received error in response to message #%d: %s (%d)', + msgno, elem.gettext(), int(elem.attr['code'])) def send_close(self, channelno=0, code=200, handle_ok=None, handle_error=None): """Send a request to close a channel to the peer.""" def handle_reply(cmd, msgno, ansno, message): if cmd == 'RPY': - logging.debug('Channel %d closed', channelno) + log.debug('Channel %d closed', channelno) self.session.channels[channelno].close() if not self.session.channels: self.session.close() @@ -684,18 +685,18 @@ elem = xmlio.parse(message.body) text = elem.gettext() code = int(elem.attr['code']) - logging.debug('Peer refused to start channel %d: %s (%d)', - channelno, text, code) + log.debug('Peer refused to start channel %d: %s (%d)', + channelno, text, code) if handle_error is not None: handle_error(code, text) - logging.debug('Requesting closure of channel %d', channelno) + log.debug('Requesting closure of channel %d', channelno) xml = xmlio.Element('close', number=channelno, code=code) return self.channel.send_msg(Payload(xml), handle_reply) def send_error(self, msgno, code, message=''): """Send an error reply to the peer.""" - logging.warning('%s (%d)', message, code) + log.warning('%s (%d)', message, code) xml = xmlio.Element('error', code=code)[message] self.channel.send_err(msgno, Payload(xml)) @@ -715,8 +716,8 @@ if cmd == 'RPY': elem = xmlio.parse(message.body) for cls in [p for p in profiles if p.URI == elem.attr['uri']]: - logging.debug('Channel %d started with profile %s', - channelno, elem.attr['uri']) + log.debug('Channel %d started with profile %s', channelno, + elem.attr['uri']) self.session.channels[channelno] = Channel(self.session, channelno, cls) break @@ -726,13 +727,13 @@ elem = xmlio.parse(message.body) text = elem.gettext() code = int(elem.attr['code']) - logging.debug('Peer refused to start channel %d: %s (%d)', - channelno, text, code) + log.debug('Peer refused to start channel %d: %s (%d)', + channelno, text, code) if handle_error is not None: handle_error(code, text) - logging.debug('Requesting start of channel %d with profiles %s', - channelno, [profile.URI for profile in profiles]) + log.debug('Requesting start of channel %d with profiles %s', channelno, + [profile.URI for profile in profiles]) xml = xmlio.Element('start', number=channelno)[ [xmlio.Element('profile', uri=profile.URI) for profile in profiles] ]
--- a/bitten/util/cmdline.py +++ b/bitten/util/cmdline.py @@ -23,6 +23,8 @@ import os.path import time +log = logging.getLogger('bitten.cmdline') + class TimeoutError(Exception): """Exception raised when the execution of a command times out.""" @@ -54,7 +56,7 @@ for idx, arg in enumerate(args): if arg.find(' ') >= 0: args[idx] = '"%s"' % arg - logging.debug('Executing %s', args) + log.debug('Executing %s', args) if self.cwd: os.chdir(self.cwd) @@ -81,7 +83,7 @@ if self.cwd: os.chdir(self.cwd) - logging.debug('Executing %s', [self.executable] + self.arguments) + log.debug('Executing %s', [self.executable] + self.arguments) pipe = popen2.Popen3([self.executable] + self.arguments, capturestderr=True) pipe.tochild.close()