Merge lp:~caio1982/ubuntu-system-image/sis-logging into lp:ubuntu-system-image/server

[Caio Begotti]

Without real logging it's nearly impossible to debug image server on Prodstack, and that's something we highly need in PES otherwise the IS team won't let us simply ssh into the machines to investigate what's going on.

[Stéphane Graber (stgraber)]

Seems reasonable though it doesn't match the general coding style.

All strings must be between double-quotes and single quotes should only be used for dict keys.

review: Needs Fixing

[lp:~caio1982/ubuntu-system-image/sis-logging]

262. By Caio Begotti on 2015-03-11

fix all single quotes logging messages as single quotes are for dict keys only

[Caio Begotti (caio1982)]

Oops, you're right. Fixed.

[lp:~caio1982/ubuntu-system-image/sis-logging]

263. By Caio Begotti on 2015-03-11

fix some pep8 warning along the way

=== modified file 'lib/systemimage/generators.py'
--- lib/systemimage/generators.py	2015-03-11 20:55:00 +0000
+++ lib/systemimage/generators.py	2015-03-11 21:18:58 +0000
@@ -17,6 +17,8 @@
 
 from hashlib import sha256
 from systemimage import diff, gpg, tree, tools
+
+import logging
 import json
 import os
 import socket
@@ -34,11 +36,15 @@
 # Global
 CACHE = {}
 
+logger = logging.getLogger(__name__)
+
 
 def list_versions(cdimage_path):
-    return sorted([version for version in os.listdir(cdimage_path)
-                   if version not in ("pending", "current")],
-                  reverse=True)
+    versions = sorted([version for version in os.listdir(cdimage_path)
+                      if version not in ("pending", "current")],
+                      reverse=True)
+    logger.debug("Versions detected: %s" % versions)
+    return versions
 
 
 def root_ownership(tarinfo):
@@ -89,6 +95,7 @@
     path = os.path.realpath(os.path.join(conf.publish_path, "pool",
                                          "%s.delta-%s.tar.xz" %
                                          (target_filename, source_filename)))
+    logger.debug("Path generated: %s" % path)
 
     # Return pre-existing entries
     if os.path.exists(path):
@@ -174,6 +181,7 @@
 
     # We need at least a path and a series
     if len(arguments) < 2:
+        logger.debug("Too few arguments")
         return None
 
     # Read the arguments
@@ -198,12 +206,15 @@
 
     # Check that the directory exists
     if not os.path.exists(cdimage_path):
+        logger.debug("Directory not found: %s" % cdimage_path)
         return None
 
     for version in list_versions(cdimage_path):
         # Skip directory without checksums
-        if not os.path.exists(os.path.join(cdimage_path, version,
-                                           "SHA256SUMS")):
+        checksum_path = os.path.exists(os.path.join(cdimage_path, version,
+                                       "SHA256SUMS"))
+        if not checksum_path:
+            logger.debug("Missing checksum: %s" % checksum_path)
             continue
 
         # Check for all the ANDROID files
@@ -212,6 +223,7 @@
                                  (series, boot_arch,
                                   environment['device_name']))
         if not os.path.exists(boot_path):
+            logger.debug("Missing boot image: %s" % boot_path)
             continue
 
         recovery_path = os.path.join(cdimage_path, version,
@@ -219,6 +231,7 @@
                                      (series, recovery_arch,
                                       environment['device_name']))
         if not os.path.exists(recovery_path):
+            logger.debug("Missing recovery image: %s" % recovery_path)
             continue
 
         system_path = os.path.join(cdimage_path, version,
@@ -226,6 +239,7 @@
                                    (series, system_arch,
                                     environment['device_name']))
         if not os.path.exists(system_path):
+            logger.debug("Missing system image: %s" % system_path)
             continue
 
         # Check if we should only import tested images
@@ -256,6 +270,7 @@
                     break
 
         if not boot_hash or not recovery_hash or not system_hash:
+            logger.debug("Boot, recovery or system checksum missing")
             continue
 
         hash_string = "%s/%s/%s" % (boot_hash, recovery_hash, system_hash)
@@ -264,6 +279,7 @@
         # Generate the path
         path = os.path.join(conf.publish_path, "pool",
                             "device-%s.tar.xz" % global_hash)
+        logger.debug("Path generated: %s" % path)
 
         # Return pre-existing entries
         if os.path.exists(path):
@@ -281,6 +297,7 @@
         temp_dir = tempfile.mkdtemp()
 
         # Generate a new tarball
+        logger.debug("Opening tarball for processing")
         target_tarball = tarfile.open(os.path.join(temp_dir, "target.tar"),
                                       "w:")
 
@@ -310,6 +327,7 @@
                            arcname="partitions/recovery.img",
                            filter=root_ownership)
 
+        logger.debug("Closing tarbal")
         target_tarball.close()
 
         # Create the pool if it doesn't exist
@@ -355,6 +373,7 @@
 
     # We need at least a path and a series
     if len(arguments) < 2:
+        logger.debug("Too few arguments")
         return None
 
     # Read the arguments
@@ -373,12 +392,15 @@
 
     # Check that the directory exists
     if not os.path.exists(cdimage_path):
+        logger.debug("Directory not found: %s" % cdimage_path)
         return None
 
     for version in list_versions(cdimage_path):
         # Skip directory without checksums
-        if not os.path.exists(os.path.join(cdimage_path, version,
-                                           "SHA256SUMS")):
+        checksum_path = os.path.exists(os.path.join(cdimage_path, version,
+                                       "SHA256SUMS"))
+        if not checksum_path:
+            logger.debug("Missing checksum: %s" % checksum_path)
             continue
 
         # Check for the rootfs
@@ -387,6 +409,7 @@
                                    (series, options.get("product", "touch"),
                                     arch))
         if not os.path.exists(rootfs_path):
+            logger.debug("Missing rootfs tarball: %s" % rootfs_path)
             continue
 
         # Check if we should only import tested images
@@ -414,6 +437,7 @@
         # Generate the path
         path = os.path.join(conf.publish_path, "pool",
                             "ubuntu-%s.tar.xz" % rootfs_hash)
+        logger.debug("Path generated: %s" % path)
 
         # Return pre-existing entries
         if os.path.exists(path):
@@ -431,6 +455,7 @@
         temp_dir = tempfile.mkdtemp()
 
         # Unpack the source tarball
+        logger.debug("Opening tarball for processing")
         tools.gzip_uncompress(rootfs_path, os.path.join(temp_dir,
                                                         "source.tar"))
 
@@ -534,6 +559,7 @@
         new_file.gname = "root"
         target_tarball.addfile(new_file)
 
+        logger.debug("Closing tarball")
         source_tarball.close()
         target_tarball.close()
 
@@ -575,6 +601,7 @@
 
     # We need at least a path and a series
     if len(arguments) < 2:
+        logger.debug("Too few arguments")
         return None
 
     # Read the arguments
@@ -593,12 +620,15 @@
 
     # Check that the directory exists
     if not os.path.exists(cdimage_path):
+        logger.debug("Directory not found: %s" % cdimage_path)
         return None
 
     for version in list_versions(cdimage_path):
         # Skip directory without checksums
-        if not os.path.exists(os.path.join(cdimage_path, version,
-                                           "SHA256SUMS")):
+        checksum_path = os.path.exists(os.path.join(cdimage_path, version,
+                                       "SHA256SUMS"))
+        if not checksum_path:
+            logger.debug("Missing checksum: %s" % checksum_path)
             continue
 
         # Check for the custom tarball
@@ -607,6 +637,7 @@
                                    (series, options.get("product", "touch"),
                                     arch))
         if not os.path.exists(custom_path):
+            logger.debug("Missing custom tarball: %s" % custom_path)
             continue
 
         # Check if we should only import tested images
@@ -634,6 +665,7 @@
         # Generate the path
         path = os.path.join(conf.publish_path, "pool",
                             "custom-%s.tar.xz" % custom_hash)
+        logger.debug("Path generated: %s" % path)
 
         # Return pre-existing entries
         if os.path.exists(path):
@@ -692,6 +724,7 @@
 
     # We need at least a path and a series
     if len(arguments) < 2:
+        logger.debug("Too few arguments")
         return None
 
     # Read the arguments
@@ -712,6 +745,7 @@
 
     # Check that the directory exists
     if not os.path.exists(cdimage_path):
+        logger.debug("Directory not found: %s" % cdimage_path)
         return None
 
     for version in list_versions(cdimage_path):
@@ -754,6 +788,7 @@
         # Generate the path
         path = os.path.join(conf.publish_path, "pool",
                             "device-%s.tar.xz" % raw_device_hash)
+        logger.debug("Path generated: %s" % path)
 
         # Return pre-existing entries
         if os.path.exists(path):
@@ -813,6 +848,7 @@
 
     # We need at least a URL
     if len(arguments) == 0:
+        logger.debug("Too few arguments")
         return None
 
     # Read the arguments
@@ -844,6 +880,7 @@
 
             # Validate the version number
             if not version or len(version.split("\n")) > 1:
+                logger.debug("Invalid or missing version number")
                 return None
 
             # Push the result in the cache
@@ -857,6 +894,8 @@
                                                  "%s-%s.tar.xz" %
                                                  (options.get("name", "http"),
                                                   version)))
+        logger.debug("Path generated: %s" % old_path)
+
         if os.path.exists(old_path):
             # Get the real version number (in case it got copied)
             if os.path.exists(old_path.replace(".tar.xz", ".json")):
@@ -876,6 +915,7 @@
                                              "%s-%s.tar.xz" %
                                              (options.get("name", "http"),
                                               global_hash)))
+        logger.debug("Path generated: %s" % path)
 
         # Return pre-existing entries
         if os.path.exists(path):
@@ -921,6 +961,8 @@
                                              "%s-%s.tar.xz" %
                                              (options.get("name", "http"),
                                               version)))
+        logger.debug("Path generated: %s" % path)
+
         # Return pre-existing entries
         if os.path.exists(path):
             # Get the real version number (in case it got copied)
@@ -969,10 +1011,12 @@
 
     # Don't generate keyring tarballs when nothing changed
     if len(environment['new_files']) == 0:
+        logger.debug("Nothing has changed, no new files")
         return None
 
     # We need a keyring name
     if len(arguments) == 0:
+        logger.debug("Too few arguments")
         return None
 
     # Read the arguments
@@ -997,6 +1041,7 @@
     path = os.path.realpath(os.path.join(conf.publish_path, "pool",
                                          "keyring-%s.tar.xz" %
                                          global_hash))
+    logger.debug("Path generated: %s" % path)
 
     # Set the version_detail string
     environment['version_detail'].append("keyring=%s" % keyring_name)
@@ -1051,6 +1096,7 @@
 
     # We need at least a channel name and a file prefix
     if len(arguments) < 3:
+        logger.debug("Too few arguments")
         return None
 
     # Read the arguments
@@ -1079,20 +1125,25 @@
     socket.setdefaulttimeout(old_timeout)
 
     if channel_name not in channel_json:
+        logger.debug("Missing channel name in JSON: %s" % channel_name)
         return None
 
     if "devices" not in channel_json[channel_name]:
+        logger.debug("Missing devices for channel name in JSON")
         return None
 
     if device_name not in channel_json[channel_name]['devices']:
+        logger.debug("Missing device name in JSON: %s" % device_name)
         return None
 
     if "index" not in (channel_json[channel_name]['devices']
                        [device_name]):
+        logger.debug("Missing index for the channel device in JSON")
         return None
 
     index_url = "%s/%s" % (base_url, channel_json[channel_name]['devices']
                            [device_name]['index'])
+    logger.debug("Index file for the devices in channel: %s" % index_url)
 
     # Fetch and validate the remote index.json
     old_timeout = socket.getdefaulttimeout()
@@ -1109,6 +1160,7 @@
     full_images = sorted([image for image in index_json['images']
                           if image['type'] == "full"],
                          key=lambda image: image['version'])
+    logger.debug("List of full images founds %s" % full_images)
 
     # No images
     if not full_images:
@@ -1121,6 +1173,8 @@
         if file_prefix == prefix:
             path = os.path.realpath("%s/%s" % (conf.publish_path,
                                                file_entry['path']))
+            logger.debug("Path generated: %s" % path)
+
             if os.path.exists(path):
                 return path
 
@@ -1187,6 +1241,7 @@
 
     # We need at least a channel name and a file prefix
     if len(arguments) < 2:
+        logger.debug("Too few arguments")
         return None
 
     # Read the arguments
@@ -1196,10 +1251,12 @@
     # Run some checks
     pub = tree.Tree(conf)
     if channel_name not in pub.list_channels():
+        logger.debug("Channel not in the published list: %s" % channel_name)
         return None
 
     if (not environment['device_name'] in
             pub.list_channels()[channel_name]['devices']):
+        logger.debug("Device not in the channel list")
         return None
 
     # Try to find the file
@@ -1208,6 +1265,7 @@
     full_images = sorted([image for image in device.list_images()
                           if image['type'] == "full"],
                          key=lambda image: image['version'])
+    logger.debug("List of full images founds %s" % full_images)
 
     # No images
     if not full_images:
@@ -1220,6 +1278,7 @@
         if file_prefix == prefix:
             path = os.path.realpath("%s/%s" % (conf.publish_path,
                                                file_entry['path']))
+            logger.debug("Path generated: %s" % path)
 
             if os.path.exists(path.replace(".tar.xz", ".json")):
                 with open(path.replace(".tar.xz", ".json"), "r") as fd:
@@ -1241,16 +1300,19 @@
 
     # Don't generate version tarballs when nothing changed
     if len(environment['new_files']) == 0:
+        logger.debug("Nothing has changed, no new files")
         return None
 
     path = os.path.realpath(os.path.join(environment['device'].path,
                             "version-%s.tar.xz" % environment['version']))
+    logger.debug("Path generated: %s" % path)
 
     # Set the version_detail string
     environment['version_detail'].append("version=%s" % environment['version'])
 
     # Don't bother re-generating a file if it already exists
     if os.path.exists(path):
+        logger.debug("Version file already exists")
         return path
 
     # Generate version_detail

=== modified file 'lib/systemimage/gpg.py'
--- lib/systemimage/gpg.py	2015-03-11 20:55:00 +0000
+++ lib/systemimage/gpg.py	2015-03-11 21:18:58 +0000
@@ -17,11 +17,14 @@
 
 import json
 import gpgme
+import logging
 import os
 import tarfile
 
 from io import BytesIO
 
+logger = logging.getLogger(__name__)
+
 
 def generate_signing_key(keyring_path, key_name, key_email, key_expiry):
     """
@@ -79,7 +82,7 @@
             destination = "%s.gpg" % path
 
     if os.path.exists(destination):
-        raise Exception("destination already exists.")
+        raise Exception("Destination already exists: %s" % destination)
 
     os.environ['GNUPGHOME'] = key_path
 
@@ -89,6 +92,8 @@
     [key] = ctx.keylist()
     ctx.signers = [key]
 
+    logger.debug("Signing file: %s" % destination)
+
     with open(path, "rb") as fd_in, open(destination, "wb+") as fd_out:
         if detach:
             retval = ctx.sign(fd_in, fd_out, gpgme.SIG_MODE_DETACH)

=== modified file 'lib/systemimage/tools.py'
--- lib/systemimage/tools.py	2015-03-11 20:55:00 +0000
+++ lib/systemimage/tools.py	2015-03-11 21:18:58 +0000
@@ -18,6 +18,7 @@
 from io import BytesIO
 
 import gzip
+import logging
 import os
 import re
 import shutil
@@ -26,6 +27,8 @@
 import tempfile
 import time
 
+logger = logging.getLogger(__name__)
+
 
 def expand_path(path, base="/"):
     """
@@ -134,7 +137,9 @@
         destination = "%s.gz" % path
 
     if os.path.exists(destination):
-        raise Exception("destination already exists.")
+        raise Exception("Destination already exists: %s" % destination)
+
+    logger.debug("Gzipping file: %s" % destination)
 
     uncompressed = open(path, "rb")
     compressed = gzip.open(destination, "wb+", level)
@@ -153,14 +158,16 @@
     """
 
     if not destination and path[-3:] != ".gz":
-        raise Exception("unspecified destination and path doesn't end"
+        raise Exception("Unspecified destination and path doesn't end"
                         " with .gz")
 
     if not destination:
         destination = path[:-3]
 
     if os.path.exists(destination):
-        raise Exception("destination already exists.")
+        raise Exception("Destination already exists: %s" % destination)
+
+    logger.debug("Ungzipping file: %s" % destination)
 
     compressed = gzip.open(path, "rb")
     uncompressed = open(destination, "wb+")
@@ -185,7 +192,9 @@
         destination = "%s.xz" % path
 
     if os.path.exists(destination):
-        raise Exception("destination already exists.")
+        raise Exception("Destination already exists: %s" % destination)
+
+    logger.debug("Xzipping file: %s" % destination)
 
     if find_on_path("pxz"):
         xz_command = "pxz"
@@ -208,14 +217,16 @@
     # NOTE: Once we can drop support for < 3.3, the new lzma module can be used
 
     if not destination and path[-3:] != ".xz":
-        raise Exception("unspecified destination and path doesn't end"
+        raise Exception("Unspecified destination and path doesn't end"
                         " with .xz")
 
     if not destination:
         destination = path[:-3]
 
     if os.path.exists(destination):
-        raise Exception("destination already exists.")
+        raise Exception("Destination already exists: %s" % destination)
+
+    logger.debug("Unxzipping file: %s" % destination)
 
     with open(destination, "wb+") as fd:
         retval = subprocess.call(['xz', '-d', '-c', path],

=== modified file 'lib/systemimage/tree.py'
--- lib/systemimage/tree.py	2015-03-11 20:55:00 +0000
+++ lib/systemimage/tree.py	2015-03-11 21:18:58 +0000
@@ -17,6 +17,7 @@
 
 import copy
 import json
+import logging
 import os
 import shutil
 import time
@@ -25,6 +26,8 @@
 from hashlib import sha256
 from systemimage import gpg, tools
 
+logger = logging.getLogger(__name__)
+
 
 # Context managers
 @contextmanager
@@ -242,7 +245,9 @@
             Remove any orphaned file from the tree.
         """
 
-        for entry in self.list_orphaned_files():
+        orphaned_files = self.list_orphaned_files()
+        for entry in orphaned_files:
+
             if os.path.isdir(entry):
                 os.rmdir(entry)
             else:
@@ -466,6 +471,7 @@
                 if tarname in referenced_files:
                     orphaned_files.remove(entry)
 
+        logger.debug("Orphaned files: %s" % orphaned_files)
         return sorted(orphaned_files)
 
     def publish_keyring(self, keyring_name):