Merge lp:~cprov/core-image-publisher/sane-logging into lp:core-image-publisher

[Celso Providelo]

Improving logging on core-image-publishing by adding standard logging extra keys (solution, service and hostname).

Improving logging on core-image-publishing by adding standard logging extra keys (solution, service and hostname).

It still a little too verbose IMO, specially the INFO points during the image handling, but we can silent it later, if necessary.

[Paul Larson (pwlars)]

+1

review: Approve

=== modified file 'core_image_publisher/__init__.py'
--- core_image_publisher/__init__.py	2015-03-30 05:48:43 +0000
+++ core_image_publisher/__init__.py	2015-03-31 16:50:17 +0000
@@ -30,8 +30,6 @@
 )
 from core_image_publisher import worker
 
-logger = logging.getLogger(__name__)
-
 
 def read_config():
     parser = argparse.ArgumentParser(description='Core image publisher.')

=== modified file 'core_image_publisher/constants.py'
--- core_image_publisher/constants.py	2015-03-30 06:17:13 +0000
+++ core_image_publisher/constants.py	2015-03-31 16:50:17 +0000
@@ -20,3 +20,34 @@
 API_VERSION = "v1"
 
 RETRY_COUNT = 3
+
+SOLUTION_NAME = "core-image-testing"
+
+SERVICE_NAME = "core-image-publisher"
+
+def _get_hostname():
+    """Return sanitized contents of /etc/hostname.
+
+    It is necessary because current juju hostnames (juju-<env-name>-machine-#)
+    are too big due to our long environment names ('<spec_name>-<MD5>').
+    Linux (DNS for RFC1035, really) only supports labels up to 64 chars and
+    the fallback varies from tool to tool, `cloud-init` chokes on longer
+    names and sets 'ubuntu', `hostnamectl` (systemd) would truncate the
+    given data. 
+
+    None of this is ideal to our applications, that's why we will operate
+    on the pristine /etc/hostname and remove the 'juju-' and '-machine' terms
+    added by juju.
+    """
+    with open('/etc/hostname') as fd:
+        hostname = fd.read()
+    return hostname.replace('juju-', '').replace('-machine', '').strip()
+
+
+HOSTNAME = _get_hostname()
+
+LOGGING_EXTRA = {
+    'solution': SOLUTION_NAME,
+    'service': SERVICE_NAME,
+    'hostname': HOSTNAME,
+}

=== modified file 'core_image_publisher/queue.py'
--- core_image_publisher/queue.py	2015-03-30 21:39:47 +0000
+++ core_image_publisher/queue.py	2015-03-31 16:50:17 +0000
@@ -88,9 +88,11 @@
         Run requested tests and posts results to the 'adt_results' queue
         for later checking.
         """
-        logger.info('Got: %r', body, extra=body)
+        extra = constants.LOGGING_EXTRA.copy()
+        extra.update(body)
+        logger.info('Got: %r', body, extra=extra)
         try:
-            requested_action = self.on_message_cb(message.payload)
+            requested_action = self.on_message_cb(body)
             if requested_action == MessageActions.Retry:
                 self.maybe_requeue_message(message)
             elif requested_action == MessageActions.Acknowledge:
@@ -102,7 +104,7 @@
             logger.error(
                 "Caught unhandled exception while processing message: %s",
                 e,
-                extra=message.payload
+                extra=extra
             )
             message.requeue()
 
@@ -119,6 +121,8 @@
         stage of the system.
 
         """
+        extra = constants.LOGGING_EXTRA.copy()
+        extra.update(message.payload)
         retry_key = "{}_retry_count".format(
             message.delivery_info.get('routing_key', '')
         )
@@ -134,7 +138,7 @@
             logger.error(
                 "Rejecting message due to retry count exceeding maximum. "
                 "Message will reside on the dead letter queue",
-                extra=message.payload
+                extra=extra
             )
             queue = self.connection.SimpleQueue(
                 'core.deadletters.{}'.format(constants.API_VERSION))

=== modified file 'core_image_publisher/worker.py'
--- core_image_publisher/worker.py	2015-03-30 21:38:58 +0000
+++ core_image_publisher/worker.py	2015-03-31 16:50:17 +0000
@@ -22,10 +22,12 @@
 import subprocess
 import tempfile
 
+from core_image_publisher.constants import LOGGING_EXTRA
+from core_image_publisher.cloud import get_glance_client
 from core_image_publisher.queue import MessageActions
-from core_image_publisher.cloud import get_glance_client
 from core_image_publisher.utils import check_call
 
+
 logger = logging.getLogger(__name__)
 
 
@@ -38,7 +40,8 @@
         self.publish_results = publisher
 
     def __call__(self, payload):
-        logger.info("Got %r", payload, extra=payload)
+        extra = LOGGING_EXTRA.copy()
+        extra.update(payload)
         try:
             image_name = payload['image_name']
             channel = payload['channel']
@@ -48,12 +51,12 @@
                 "Unable to deserialize message payload - "
                 "rejecting message: %s",
                 e,
-                extra=payload
+                extra=extra
             )
             return MessageActions.Retry
 
         with tempfile.TemporaryDirectory() as tmpdir:
-            logger.info("Beginning image download.", extra=payload)
+            logger.info("Beginning image download.", extra=extra)
             try:
                 image_path = download_image(
                     image_name,
@@ -65,10 +68,10 @@
                 logger.error(
                     "Unable to download core image: %s",
                     e,
-                    extra=payload
+                    extra=extra
                 )
                 return MessageActions.Retry
-            logger.info("Ubuntu Core image downloaded OK.", extra=payload)
+            logger.info("Ubuntu Core image downloaded OK.", extra=extra)
 
             try:
                 nova_image_path = convert_nova_image(image_path)
@@ -76,12 +79,13 @@
                 logger.error(
                     "Unable to convert core image to qcow2 image: %s",
                     e,
-                    extra=payload)
+                    extra=extra)
                 return MessageActions.Retry
-            logger.info("Image converted to qcow2 OK.", extra=payload)
+            logger.info("Image converted to qcow2 OK.", extra=extra)
 
             try:
-                logger.info("Beginning image upload to glance...")
+                logger.info("Beginning image upload to glance...",
+                            extra=extra)
                 glance_image_name = upload_image_to_glance(
                     nova_image_path,
                     self._config
@@ -90,14 +94,14 @@
                 logger.error(
                     "Unable to upload image to glance: %s",
                     e,
-                    extra=payload
+                    extra=extra
                 )
                 return MessageActions.Retry
-            logger.info("Image uploaded to glance OK.", extra=payload)
+            logger.info("Image uploaded to glance OK.", extra=extra)
 
         payload['nova_image'] = glance_image_name
         self.publish_results(payload)
-        logger.info("Processing completed.", extra=payload)
+        logger.info("Processing completed.", extra=extra)
         return MessageActions.Acknowledge