From 338530658aac87d5e36b3b73252febffa142663d Mon Sep 17 00:00:00 2001 From: Jay Faulkner Date: Fri, 24 Jan 2014 14:20:14 -0800 Subject: [PATCH 1/4] add(logging): Log and time various events - Log what's happening at various appropriate levels - Log the time it takes to download and the time it takes to write the image --- teeth_agent/standby.py | 24 +++++++++++++++++++++--- 1 file changed, 21 insertions(+), 3 deletions(-) diff --git a/teeth_agent/standby.py b/teeth_agent/standby.py index 21462c561..070cdc6ad 100644 --- a/teeth_agent/standby.py +++ b/teeth_agent/standby.py @@ -16,15 +16,18 @@ limitations under the License. import hashlib import os -import subprocess - import requests +import structlog +import subprocess +import time from teeth_agent import base from teeth_agent import configdrive from teeth_agent import errors from teeth_agent import hardware +log = structlog.get_logger() + def _configdrive_location(): return '/tmp/configdrive' @@ -40,14 +43,17 @@ def _path_to_script(script): def _write_image(image_info, configdrive_dir, device): + starttime = time.time() image = _image_location(image_info) script = _path_to_script('shell/makefs.sh') command = ['/bin/bash', script, configdrive_dir, image, device] - + log.info('Writing image via {}'.format(' '.join(command))) exit_code = subprocess.call(command) if exit_code != 0: raise errors.ImageWriteError(exit_code, device) + totaltime = int(time.time() - starttime) + log.info('Image written to {} in {}s'.format(device, totaltime)) def _request_url(image_info, url): @@ -58,11 +64,14 @@ def _request_url(image_info, url): def _download_image(image_info): + starttime = time.time() resp = None for url in image_info['urls']: try: + log.info("Attempting to download image from {}".format(url)) resp = _request_url(image_info, url) except errors.ImageDownloadError: + log.warning("Image download failed from {}".format(url)) continue else: break @@ -77,6 +86,9 @@ def _download_image(image_info): except Exception: raise errors.ImageDownloadError(image_info['id']) + totaltime = int(time.time() - starttime) + log.info("Image {} downloaded in {}s".format(image_location, totaltime)) + if not _verify_image(image_info, image_location): raise errors.ImageChecksumError(image_info['id']) @@ -87,14 +99,19 @@ def _verify_image(image_info, image_location): algo = getattr(hashlib, k, None) if algo is None: continue + log.debug('Verifying {} against {}:{}'.format(image_location, k, v)) hash_ = algo(open(image_location).read()).hexdigest() if hash_ == v: return True + else: + logline = 'Image at {} with {}: {} does not match expected {}: {}' + log.warning(logline.format(image_location, k, hash_, k, v)) return False def _run_image(): script = _path_to_script('shell/reboot.sh') + log.info("Rebooting system") command = ['/bin/bash', script] # this should never return if successful exit_code = subprocess.call(command) @@ -118,6 +135,7 @@ class PrepareImageCommand(base.AsyncCommandResult): device = hardware.get_manager().get_os_install_device() _download_image(image_info) + log.debug('Writing configdrive to {}'.format(location)) configdrive.write_configdrive(location, metadata, files) _write_image(image_info, location, device) From 1d756dde4bf60e761c8aaecdb37666410f77a8fe Mon Sep 17 00:00:00 2001 From: Jay Faulkner Date: Fri, 24 Jan 2014 14:55:33 -0800 Subject: [PATCH 2/4] fix(log): Log attrs separately instead of w/format --- teeth_agent/standby.py | 20 +++++++++++--------- 1 file changed, 11 insertions(+), 9 deletions(-) diff --git a/teeth_agent/standby.py b/teeth_agent/standby.py index 070cdc6ad..a362a9252 100644 --- a/teeth_agent/standby.py +++ b/teeth_agent/standby.py @@ -48,12 +48,12 @@ def _write_image(image_info, configdrive_dir, device): script = _path_to_script('shell/makefs.sh') command = ['/bin/bash', script, configdrive_dir, image, device] - log.info('Writing image via {}'.format(' '.join(command))) + log.info('Writing image', command=' '.join(command)) exit_code = subprocess.call(command) if exit_code != 0: raise errors.ImageWriteError(exit_code, device) totaltime = int(time.time() - starttime) - log.info('Image written to {} in {}s'.format(device, totaltime)) + log.info('Image written', device=device, seconds=totaltime, image=image) def _request_url(image_info, url): @@ -68,10 +68,11 @@ def _download_image(image_info): resp = None for url in image_info['urls']: try: - log.info("Attempting to download image from {}".format(url)) + log.info("Attempting to download image", url=url) resp = _request_url(image_info, url) except errors.ImageDownloadError: - log.warning("Image download failed from {}".format(url)) + failtime = time.time() - starttime + log.warning("Image download failed", url=url, seconds=failtime) continue else: break @@ -87,7 +88,7 @@ def _download_image(image_info): raise errors.ImageDownloadError(image_info['id']) totaltime = int(time.time() - starttime) - log.info("Image {} downloaded in {}s".format(image_location, totaltime)) + log.info("Image downloaded", image=image_location, seconds=totaltime) if not _verify_image(image_info, image_location): raise errors.ImageChecksumError(image_info['id']) @@ -99,13 +100,14 @@ def _verify_image(image_info, image_location): algo = getattr(hashlib, k, None) if algo is None: continue - log.debug('Verifying {} against {}:{}'.format(image_location, k, v)) + log.debug('Verifying image', image=image_location, algo=k, + passed_hash=v) hash_ = algo(open(image_location).read()).hexdigest() if hash_ == v: return True else: - logline = 'Image at {} with {}: {} does not match expected {}: {}' - log.warning(logline.format(image_location, k, hash_, k, v)) + log.warning('Image verification failed', image=image_location, + algo=k, imagehash=hash_, passed_hash=v) return False @@ -135,7 +137,7 @@ class PrepareImageCommand(base.AsyncCommandResult): device = hardware.get_manager().get_os_install_device() _download_image(image_info) - log.debug('Writing configdrive to {}'.format(location)) + log.debug('Writing configdrive', location=location) configdrive.write_configdrive(location, metadata, files) _write_image(image_info, location, device) From 0217e5a5de10f5118fbd21e4ecb54adb72e7c78c Mon Sep 17 00:00:00 2001 From: Jay Faulkner Date: Fri, 24 Jan 2014 15:02:11 -0800 Subject: [PATCH 3/4] fix(logging): Don't drop precision on time values --- teeth_agent/standby.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/teeth_agent/standby.py b/teeth_agent/standby.py index a362a9252..17f20239c 100644 --- a/teeth_agent/standby.py +++ b/teeth_agent/standby.py @@ -52,7 +52,7 @@ def _write_image(image_info, configdrive_dir, device): exit_code = subprocess.call(command) if exit_code != 0: raise errors.ImageWriteError(exit_code, device) - totaltime = int(time.time() - starttime) + totaltime = time.time() - starttime log.info('Image written', device=device, seconds=totaltime, image=image) @@ -87,7 +87,7 @@ def _download_image(image_info): except Exception: raise errors.ImageDownloadError(image_info['id']) - totaltime = int(time.time() - starttime) + totaltime = time.time() - starttime log.info("Image downloaded", image=image_location, seconds=totaltime) if not _verify_image(image_info, image_location): From 69cebd1e4806df6306b8c90181c25a120a5f46f0 Mon Sep 17 00:00:00 2001 From: Jay Faulkner Date: Fri, 24 Jan 2014 15:14:01 -0800 Subject: [PATCH 4/4] fix(style): Fix style to match rest of project --- teeth_agent/standby.py | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/teeth_agent/standby.py b/teeth_agent/standby.py index 17f20239c..53a9d0a69 100644 --- a/teeth_agent/standby.py +++ b/teeth_agent/standby.py @@ -100,14 +100,19 @@ def _verify_image(image_info, image_location): algo = getattr(hashlib, k, None) if algo is None: continue - log.debug('Verifying image', image=image_location, algo=k, + log.debug('Verifying image', + image=image_location, + algo=k, passed_hash=v) hash_ = algo(open(image_location).read()).hexdigest() if hash_ == v: return True else: - log.warning('Image verification failed', image=image_location, - algo=k, imagehash=hash_, passed_hash=v) + log.warning('Image verification failed', + image=image_location, + algo=k, + imagehash=hash_, + passed_hash=v) return False