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
This commit is contained in:
Sam Yaple 2015-08-27 15:49:44 +00:00
parent 4da40a0ab9
commit 59dc528909

@ -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