Merge lp:~cprov/adt-cloud-worker/log-cleanup into lp:adt-cloud-worker

[Celso Providelo]

Suppressing adt-run output from the logs, adding logstash & file logging handlers along with some messaging cleanup.

Suppressing adt-run output from the logs, adding logstash & file logging handlers along with some messaging cleanup.

[Thomi Richards (thomir-deactivatedaccount)]

<thomi> cprov: ok, only thing is, best practise is to do: logger.info("%s", var) not logger.info("%s" % (var)) or logger.info("{}".format(var))
<cprov> thomi: I noticed in your MPs, let me fix mine
<thomi> cprov: also, in my MPs I set 'requests' to WARNING
<thomi> best make them all the same I guess
<thomi> cprov: otherwise, looks good

Looks good - suggest you fix the above two issues.

review: Approve

[lp:~cprov/adt-cloud-worker/log-cleanup]

30. By Celso Providelo on 2015-03-20

Fixing logging format style.

31. By Celso Providelo on 2015-03-20

'requests' logging set to WARNING.

[Celso Providelo (cprov)]

Both fixed, thanks.

=== modified file 'adt-service.conf'
--- adt-service.conf	2015-03-16 20:50:34 +0000
+++ adt-service.conf	2015-03-20 01:06:08 +0000
@@ -10,3 +10,8 @@
 os_auth_url = http://172.20.161.138:5000/v2.0/
 os_region_name = bot-prototype
 extra_args = --net-id=415a0839-eb05-4e7a-907c-413c657f4bf5
+
+[logstash]
+host = localhost
+port = 5959
+version = 1

=== modified file 'adt_cloud_worker/__init__.py'
--- adt_cloud_worker/__init__.py	2015-03-19 03:08:53 +0000
+++ adt_cloud_worker/__init__.py	2015-03-20 01:06:08 +0000
@@ -23,9 +23,9 @@
 import argparse
 import configparser
 import kombu
-from kombu.log import get_logger
 from kombu.mixins import ConsumerMixin
-from kombu.utils.debug import setup_logging
+import logging
+import logstash
 import os
 import socket
 import subprocess
@@ -44,7 +44,8 @@
 )
 API_VERSION = "v1"
 
-logger = get_logger(__name__)
+
+logger = logging.getLogger(__name__)
 
 
 class AdtNovaWorker(ConsumerMixin):
@@ -79,8 +80,8 @@
         Run requested tests and posts results to the 'adt_results' queue
         for later checking.
         """
-        logger.info('Got: {}'.format(body))
         body['worker'] = self.worker_name
+        logger.info('Received message request: %s', body, extra=body)
 
         # Run requested tests safely.
         tarball_path = None
@@ -97,8 +98,12 @@
                     'nova', 'extra_args').split()
                 adt_kwargs['nova_flavor'] = get_default_testbed_flavor()
                 arguments = _make_adt_argument_list(adt_kwargs)
-
+                logger.info(
+                    'Running adt-run with: %s', ' '.join(arguments),
+                    extra=body)
                 body['exit_code'] = run_adt(arguments)
+                logger.info(
+                    'Exit code: %s', body['exit_code'], extra=body)
                 _create_run_metadata_file(result_dir, body)
                 tarball_path = _create_tarball_from_directory(
                     result_dir,
@@ -110,18 +115,19 @@
                 upload_tarball_to_swift_container(tarball_path, container_name)
         except Exception as e:
             # Unexpected failures ...
-            logger.error(e, exc_info=True)
             body['exit_code'] = '100'
+            logger.error(e, exc_info=True, extra=body)
         finally:
-            # The post results
-            # TODO: send error logging to result-checker in the message
-            queue = self.connection.SimpleQueue('adt.results.{}'.format(API_VERSION))
+            logger.info('Posting results: %s', body, extra=body)
+            # TODO: send error logging to result-checker in the message.
+            queue = self.connection.SimpleQueue(
+                'adt.results.{}'.format(API_VERSION))
             queue.put(body)
             queue.close()
             if tarball_path and os.path.exists(tarball_path):
                 os.remove(tarball_path)
             message.ack()
-            logger.info('Done!')
+            logger.info('Done!', extra=body)
 
 
 def _create_run_metadata_file(directory, request):
@@ -174,14 +180,11 @@
 
     Returns the exit code from adt-run.
     """
-    # TODO: We probably want something more clever here:
-    try:
-        subprocess.check_call(['adt-run'] + arguments)
-    except subprocess.CalledProcessError as e:
-        # log?
-        # TODO: filter log content to avoid leaking cloud credentials.
-        return e.returncode
-    return 0
+    cmd_line = ['adt-run'] + arguments
+    proc = subprocess.Popen(
+        cmd_line, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
+    proc.communicate()
+    return proc.returncode
 
 
 def _make_adt_argument_list(request_configuration):
@@ -250,9 +253,42 @@
     return tarball_path
 
 
+def configure_logging(config):
+    root_logger = logging.getLogger()
+    root_logger.setLevel(logging.INFO)
+
+    # Silence requests logging, which is created by nova, keystone and swift.
+    requests_logger = logging.getLogger('requests')
+    requests_logger.setLevel(logging.WARNING)
+
+    # If there is no ./logs directory, fallback to stderr.
+    log_path = os.path.abspath(os.path.join(__file__, '../../logs/app.log'))
+    log_dir = os.path.dirname(log_path)
+    if os.path.exists(log_dir):
+        handler = logging.FileHandler(log_path)
+    else:
+        print("'logs' directory '{}' does not exist, using stderr "
+              "for app log.".format(log_dir))
+        handler = logging.StreamHandler()
+
+    handler.setFormatter(
+        logging.Formatter(
+            '%(asctime)s  %(name)s %(levelname)s: %(message)s'
+        )
+    )
+    root_logger.addHandler(handler)
+
+    if 'logstash' in config:
+        root_logger.addHandler(
+            logstash.LogstashHandler(
+                config['logstash']['host'],
+                int(config['logstash']['port']),
+                int(config['logstash']['version'])
+            )
+        )
+
+
 def main():
-    setup_logging(loglevel='DEBUG', loggers=[''])
-
     parser = argparse.ArgumentParser(
         description='ADT cloud worker ...')
     parser.add_argument('-c', '--conf', default='adt-service.conf',
@@ -263,6 +299,8 @@
     config = configparser.ConfigParser()
     config.read(args.conf)
 
+    configure_logging(config)
+
     set_config_dict(config)
 
     amqp_uris = config.get('amqp', 'uris').split()

=== modified file 'requirements.txt'
--- requirements.txt	2015-03-08 22:20:15 +0000
+++ requirements.txt	2015-03-20 01:06:08 +0000
@@ -1,5 +1,6 @@
 kombu==3.0.24
 python-keystoneclient==1.2.0
+python-logstash==0.4.2
 python-novaclient==2.22.0
 python-swiftclient==2.3.1