Unify output formatting, add logging

Since there is no central storage for the restart actions and the tests
at the moment, they should have timestamped output to correlate events.
Using a standard format will make this easier to do programmatically,
too.

The output is sent both to stdout and a log file. Additionally, Ansible
output is suppressed now, so it doesn't pollute the console. Log times
are in UTC, to avoid timezone mismatches between nodes (observed in
multi-node AIOs).

The `configure_logging` function was copied into the tests/keystone.py
file instead of put into a common module in order to keep that file a
standalone unit for the time being.

Change-Id: I399d1827a8559896ca87e45c00241293ccd033d2

bowling_ball/rolling_restart.py

@@ -17,11 +17,15 @@
 
 import argparse
 import json
+import logging
 import os
 import subprocess
 import sys
 import time
 
+logger = logging.getLogger(__name__)
+
+
 CONF_DIR = os.path.join('/', 'etc', 'openstack_deploy')
 INVENTORY_FILE = os.path.join(CONF_DIR, 'openstack_inventory.json')
 CONF_FILE = os.path.join(CONF_DIR, 'openstack_user_config.yml')
@@ -33,6 +37,25 @@ START_TEMPLATE = 'ansible -i inventory -m shell -a\
         "lxc-start -dn {container}" {host}'
 
 
+def configure_logging():
+    logger.setLevel(logging.INFO)
+    console = logging.StreamHandler()
+    logfile = logging.FileHandler('/var/log/rolling_restart.log', 'a')
+
+    console.setLevel(logging.INFO)
+    logfile.setLevel(logging.INFO)
+
+    formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
+    # Make sure we're using UTC for everything.
+    formatter.converter = time.gmtime
+
+    console.setFormatter(formatter)
+    logfile.setFormatter(formatter)
+
+    logger.addHandler(console)
+    logger.addHandler(logfile)
+
+
 def args(arg_list):
     parser = argparse.ArgumentParser(
         usage='%(prog)s',
@@ -100,18 +123,23 @@ def rolling_restart(containers, inventory, wait=120):
     wait is the number of seconds to wait between stopping and starting a
     container
     """
+    # Grab a handle to /dev/null so we don't pollute console output with
+    # Ansible stuff
+    FNULL = open(os.devnull, 'w')
     for container in containers:
         host = inventory['_meta']['hostvars'][container]['physical_host']
 
         stop_cmd = STOP_TEMPLATE.format(container=container, host=host)
-        print("Stopping {container}".format(container=container))
+        logger.info(("Stopping {container}".format(container=container)))
-        subprocess.check_call(stop_cmd, shell=True)
+        subprocess.check_call(stop_cmd, shell=True, stdout=FNULL,
+                              stderr=subprocess.STDOUT)
 
         time.sleep(wait)
 
         start_cmd = START_TEMPLATE.format(container=container, host=host)
-        subprocess.check_call(start_cmd, shell=True)
+        subprocess.check_call(start_cmd, shell=True, stdout=FNULL,
-        print("Started {container}".format(container=container))
+                              stderr=subprocess.STDOUT)
+        logger.info("Started {container}".format(container=container))
 
 
 def main():
@@ -119,6 +147,8 @@ def main():
     service = all_args['service']
     wait = all_args['wait']
 
+    configure_logging()
+
     inventory = read_inventory(INVENTORY_FILE)
     containers = get_containers(service, inventory)
 

bowling_ball/tests/keystone.py

@@ -21,10 +21,34 @@ from keystoneauth1 import session
 from keystoneauth1.exceptions.connection import ConnectFailure
 from keystoneauth1.exceptions.http import InternalServerError
 from keystoneclient.v3 import client
+import logging
 import os
 import sys
 import time
 
+logger = logging.getLogger(__name__)
+
+
+def configure_logging():
+    logger.setLevel(logging.INFO)
+    console = logging.StreamHandler()
+    logfile = logging.FileHandler('/var/log/keystone_query.log', 'a')
+
+    console.setLevel(logging.INFO)
+    logfile.setLevel(logging.INFO)
+
+    formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
+    # Make sure we're using UTC for everything.
+    formatter.converter = time.gmtime
+
+    console.setFormatter(formatter)
+    logfile.setFormatter(formatter)
+
+    logger.addHandler(console)
+    logger.addHandler(logfile)
+
+configure_logging()
+
 auth_url = os.environ['OS_AUTH_URL']
 password = os.environ['OS_PASSWORD']
 
@@ -50,11 +74,11 @@ try:
             if disconnected:
                 dis_delta = end_time - disconnected
                 disconnected = None
-                print("Reconnect {}s".format(dis_delta.total_seconds()))
+                logger.info("Reconnect {}s".format(dis_delta.total_seconds()))
 
             delta = end_time - start_time
 
-            print("New list: {]s.".format(delta.total_seconds()))
+            logger.info("New list: {}s.".format(delta.total_seconds()))
         except (ConnectFailure, InternalServerError):
             if not disconnected:
                 disconnected = datetime.datetime.now()