Merge lp:~cprov/snappy-proposed-image-builder/logging-extra into lp:snappy-proposed-image-builder

[Celso Providelo]

Using ExtraLogger to avoid passing 'extra' when logging and also setting HOME to the temporary dir when calling u-d-f (caches will be purged).

Using ExtraLogger to avoid passing 'extra' when logging and also setting HOME to the temporary dir when calling u-d-f (caches will be purged).

[Celso Providelo (cprov)]

Self approving ...

review: Approve

=== modified file 'snappy_proposed_image_builder/__init__.py'
--- snappy_proposed_image_builder/__init__.py	2015-05-27 19:13:29 +0000
+++ snappy_proposed_image_builder/__init__.py	2015-06-13 01:58:46 +0000
@@ -37,7 +37,8 @@
 
 
 def read_config():
-    parser = argparse.ArgumentParser(description='Core image builder.')
+    parser = argparse.ArgumentParser(
+        description='Snappy-proposed image builder.')
     parser.add_argument(
         '-c',
         '--conf',

=== modified file 'snappy_proposed_image_builder/worker.py'
--- snappy_proposed_image_builder/worker.py	2015-06-05 21:23:37 +0000
+++ snappy_proposed_image_builder/worker.py	2015-06-13 01:58:46 +0000
@@ -25,6 +25,7 @@
 import tempfile
 
 from uservice_utils.queue import MessageActions
+from uservice_utils.logging import ExtraLogger
 
 from snappy_proposed_image_builder.constants import LOGGING_EXTRA
 from snappy_proposed_image_builder.cloud import get_glance_client
@@ -34,6 +35,7 @@
 )
 
 
+logging.setLoggerClass(ExtraLogger)
 logger = logging.getLogger(__name__)
 
 
@@ -56,6 +58,8 @@
     def __call__(self, payload):
         extra = LOGGING_EXTRA.copy()
         extra.update(payload)
+        logger.set_extra_args(extra)
+
         try:
             release = payload['release']
             channel = payload['channel']
@@ -67,7 +71,6 @@
                 "Unable to deserialize message payload - "
                 "rejecting message: %s",
                 e,
-                extra=extra
             )
             return MessageActions.Retry
 
@@ -79,7 +82,7 @@
         payload['device_version'] = device_version
 
         with tempfile.TemporaryDirectory() as tmpdir:
-            logger.info("Beginning rootfs download.", extra=extra)
+            logger.info("Beginning rootfs download.")
             try:
                 rootfs_path = download_rootfs(
                     image_version,
@@ -92,7 +95,6 @@
                 logger.error(
                     "Unable to download core image: %s",
                     e,
-                    extra=extra
                 )
                 return MessageActions.Retry
 
@@ -100,15 +102,17 @@
             MAX_RETRIES = 3
             count = MAX_RETRIES
             while count > 0:
-                new_rootfs_path = add_proposed_packages(rootfs_path,
-                                                        image_binaries,
-                                                        source_version)
+                new_rootfs_path = add_proposed_packages(
+                    rootfs_path,
+                    image_binaries,
+                    source_version,
+                )
                 if new_rootfs_path is not None:
                     break
 
                 # try removing the rootfs as it sometimes is corrupted.
                 # XXX: find out why it's getting corrupted.
-                logger.info("Retrying rootfs download.", extra=extra)
+                logger.info("Retrying rootfs download.")
                 os.remove(rootfs_path)
                 try:
                     rootfs_path = download_rootfs(
@@ -122,7 +126,6 @@
                     logger.error(
                         "Unable to download core image: %s",
                         e,
-                        extra=extra
                     )
                     return MessageActions.Retry
 
@@ -150,10 +153,9 @@
                 logger.error(
                     "Unable to build the image: %s",
                     e,
-                    extra=extra
                 )
                 return MessageActions.Retry
-            logger.info("Ubuntu Core image build OK.", extra=extra)
+            logger.info("Ubuntu Core image build OK.")
 
             try:
                 nova_image_path = convert_nova_image(image_path)
@@ -161,29 +163,27 @@
                 logger.error(
                     "Unable to convert core image to qcow2 image: %s",
                     e,
-                    extra=extra)
+                )
                 return MessageActions.Retry
-            logger.info("Image converted to qcow2 OK.", extra=extra)
+            logger.info("Image converted to qcow2 OK.")
 
             try:
-                logger.info("Beginning image upload to glance...",
-                            extra=extra)
+                logger.info("Beginning image upload to glance...")
                 glance_image_id = upload_image_to_glance(
                     nova_image_path,
-                    self._config
+                    self._config,
                 )
             except Exception as e:
                 logger.error(
                     "Unable to upload image to glance: %s",
                     e,
-                    extra=extra
                 )
                 return MessageActions.Retry
-            logger.info("Image uploaded to glance OK.", extra=extra)
+            logger.info("Image uploaded to glance OK.")
 
         payload['nova_image_id'] = glance_image_id
         self.publish_results(payload)
-        logger.info("Processing completed.", extra=extra)
+        logger.info("Processing completed.")
         return MessageActions.Acknowledge
 
 
@@ -255,7 +255,6 @@
 
 
 def add_proposed_packages(rootfs_path, image_binaries, source_version):
-
     new_rootfs_path = rootfs_path.replace('.tar.xz', '-modified.tar.xz')
 
     ROOTFS_BASE_DIR = 'system'
@@ -367,6 +366,12 @@
 def build_image(name, rootfs_path, release, channel, device, tmpdir):
     """Download the ubuntu code image, return a path to it on disk."""
     image_path = os.path.join(tmpdir, 'snappy-proposed-{}.img'.format(name))
+    udf_env = {
+        # u-d-f fills '~/.cache/ubuntuimages/' on downloads,
+        # not particulary useful to us, unless we only have one
+        # worker and perform testing retries.
+        'HOME': tmpdir,
+    }
     cmd = ['sudo',
            ubuntu_device_flash,
            '--revision', name,
@@ -379,7 +384,7 @@
            '--developer-mode',
            '--cloud',
            release]
-    check_call(cmd)
+    check_call(cmd, env=udf_env)
 
     cmd = ['sudo',
            'rm',
@@ -410,7 +415,6 @@
     """
     Upload the nova image to glance, returning the id of the image in glance.
     """
-    extra = LOGGING_EXTRA.copy()
     glance = get_glance_client(config)
     image_name = os.path.basename(nova_image_path)
     image = glance.images.create(
@@ -419,13 +423,12 @@
         disk_format='qcow2',
         container_format='bare',
     )
-    logger.info("Uploaded %s with ID %s.", image_name, image.id, extra=extra)
+    logger.info("Uploaded %s with ID %s.", image_name, image.id)
     return image.id
 
 
 def _get_version_string_output(release, channel, device):
     """Obtains a bytestring of the images info from the core image server"""
-    extra = LOGGING_EXTRA.copy()
     cmd = [
         ubuntu_device_flash,
         'query',
@@ -437,7 +440,7 @@
     try:
         latest_image_info = subprocess.check_output(cmd)
     except subprocess.CalledProcessError as e:
-        logger.error(e, exc_info=True, extra=extra)
+        logger.error(e, exc_info=True)
     finally:
         return latest_image_info