From 59dc528909411f1e1f5e4ae76a239eea62916d23 Mon Sep 17 00:00:00 2001 From: Sam Yaple Date: Thu, 27 Aug 2015 15:49:44 +0000 Subject: [PATCH] Make logging more better build.py logging has never done what people think it should do, this patch aims to fix that. All logs related to an image will now be printed with the image name prefixed to the message. To acheive this we have to print out the messages as we get them, even in parallel building mode. If you wish to view the logs for an single image, a grep would be advised to filter the logs. Change-Id: I15ae361892f06a47afafe73750ddd8628697cfea Implements: blueprint build-script --- kolla/cmd/build.py | 67 ++++++++++++++++++++++++++++------------------ 1 file changed, 41 insertions(+), 26 deletions(-) diff --git a/kolla/cmd/build.py b/kolla/cmd/build.py index 11e63073aa..d94d8b29bc 100755 --- a/kolla/cmd/build.py +++ b/kolla/cmd/build.py @@ -54,7 +54,6 @@ class WorkerThread(Thread): self.nocache = args['no_cache'] self.forcerm = not args['keep'] self.retries = args['retries'] - self.threads = args['threads'] self.dc = docker.Client(**docker.utils.kwargs_from_env()) super(WorkerThread, self).__init__() @@ -65,9 +64,9 @@ class WorkerThread(Thread): # an 'error' status for child in image['children']: self.queue.put(child) - LOG.debug('Added image {} to queue'.format(child['name'])) + LOG.debug('{}:Added image to queue'.format(child['name'])) self.queue.task_done() - LOG.debug('Processed: {}'.format(image['name'])) + LOG.debug('{}:Processed'.format(image['name'])) def run(self): """Executes tasks until the queue is empty""" @@ -93,7 +92,8 @@ class WorkerThread(Thread): dest_tar = os.path.join(dest_dir, source['dest']) if source.get('type') == 'url': - LOG.debug("Getting tarball from " + source['source']) + LOG.debug("{}:Getting tarball from {}".format(image['name'], + source['source'])) r = requests.get(source['source']) if r.status_code == 200: @@ -101,8 +101,8 @@ class WorkerThread(Thread): f.write(r.content) else: LOG.error( - 'Failed to download tarball: status_code {}'.format( - r.status_code)) + '{}:Failed to download tarball: status_code {}'.format( + image['name'], r.status_code)) image['status'] = "error" return @@ -110,13 +110,16 @@ class WorkerThread(Thread): clone_dir = os.path.splitext(dest_tar)[0] + \ '-' + source['reference'] try: - LOG.debug("Cloning from " + source['source']) + LOG.debug("{}:Cloning from {}".format(image['name'], + source['source'])) git.Git().clone(source['source'], clone_dir) - LOG.debug("Git checkout by reference " + source['reference']) + LOG.debug("{}:Git checkout by reference {}".format( + image['name'], source['reference'])) git.Git(clone_dir).checkout(source['reference']) except Exception as e: - LOG.error("Failed to get source from git") - LOG.error("Error: " + str(e)) + LOG.error("{}:Failed to get source from git".format( + image['name'])) + LOG.error("{}:Error:{}".format(image['name'], str(e))) # clean-up clone folder to retry shutil.rmtree(clone_dir) image['status'] = "error" @@ -126,7 +129,8 @@ class WorkerThread(Thread): tar.add(clone_dir, arcname=os.path.basename(clone_dir)) else: - LOG.error("Wrong source type: " + source.get('type')) + LOG.error("{}:Wrong source type '{}'".format(image['name'], + source.get('type'))) image['status'] = "error" return @@ -134,20 +138,20 @@ class WorkerThread(Thread): os.utime(os.path.join(dest_dir, source['dest']), (0, 0)) def builder(self, image): - LOG.debug('Processing: {}'.format(image['name'])) + LOG.debug('{}:Processing'.format(image['name'])) if image['status'] == 'unmatched': return if (image['parent'] is not None and image['parent']['status'] in ['error', 'parent_error', 'connection_error']): - LOG.error('Parent image error\'d with message "{}"'.format( - image['parent']['status'])) + LOG.error('{}:Parent image error\'d with message "{}"'.format( + image['name'], image['parent']['status'])) image['status'] = "parent_error" return image['status'] = "building" - LOG.info('Building {}'.format(image['name'])) + LOG.info('{}:Building'.format(image['name'])) if 'source' in image and 'source' in image['source']: self.process_source(image) @@ -168,21 +172,22 @@ class WorkerThread(Thread): if 'stream' in stream: image['logs'] = image['logs'] + stream['stream'] - if self.threads == 1: - LOG.info('{}:{}'.format(image['name'], - stream['stream'].rstrip())) + for line in stream['stream'].split('\n'): + if line: + LOG.info('{}:{}'.format(image['name'], line)) if 'errorDetail' in stream: image['status'] = "error" - LOG.error(stream['errorDetail']['message']) + LOG.error('{}:Error\'d with the following message'.format( + image['name'])) + for line in stream['errorDetail']['message'].split('\n'): + if line: + LOG.error('{}:{}'.format(image['name'], line)) return image['status'] = "built" - if self.threads == 1: - LOG.info('Built: {}'.format(image['name'])) - else: - LOG.info('{}Built: {}'.format(image['logs'], image['name'])) + LOG.info('{}:Built'.format(image['name'])) def arg_parser(): @@ -354,7 +359,7 @@ class KollaWorker(object): image['parent']['status'] != 'matched'): image = image['parent'] image['status'] = 'matched' - LOG.debug('Matched image {}'.format(image['name'])) + LOG.debug('{}:Matched regex'.format(image['name'])) else: image['status'] = 'unmatched' else: @@ -363,6 +368,16 @@ class KollaWorker(object): def summary(self): """Walk the dictionary of images statuses and print results""" + # For debug we print the logs again if the image error'd. This is to + # to help us debug and it will be extra helpful in the gate. + for image in self.images: + if image['status'] == 'error': + LOG.debug("{}:Failed with the following logs".format( + image['name'])) + for line in image['logs'].split('\n'): + if line: + LOG.debug("{}:{}".format(image['name'], ''.join(line))) + self.get_image_statuses() if self.image_statuses_good: @@ -440,7 +455,7 @@ class KollaWorker(object): self.config.get(image['name'], 'reference') except ConfigParser.NoSectionError: - LOG.debug('No config found for {}'.format(image['name'])) + LOG.debug('{}:No config found'.format(image['name'])) pass self.images.append(image) @@ -473,7 +488,7 @@ class KollaWorker(object): for image in self.images: if image['parent'] is None: queue.put(image) - LOG.debug('Added image {} to queue'.format(image['name'])) + LOG.debug('{}:Added image to queue'.format(image['name'])) return queue