Improve how jobs log

Improve the logging for jobs in turbo-hipster so that if something fails
in a plugin (for example the db migration checks) it is logged and uploaded
appropriately.

This causes multiple logs per job.

Change-Id: I01e73ea418defbc0c1abd3b2b4357a816ddf99c3

8 files changed, 382 insertions, 63 deletions

diff --git a/test-requirements.txt b/test-requirements.txt
index 3f207f0..a08c619 100644
--- a/test-requirements.txt
+++ b/test-requirements.txt
@@ -7,6 +7,9 @@ coverage>=3.6
 
 sphinx>=1.1.2,!=1.2.0,!=1.3b1,<1.3
 discover
+mock
+six
+unittest2
 python-subunit
 testrepository>=0.0.13
 testtools>=0.9.27
diff --git a/tests/base.py b/tests/base.py
index a79b535..d4ff9da 100644
--- a/tests/base.py
+++ b/tests/base.py
@@ -66,17 +66,21 @@ class TestWithGearman(testtools.TestCase):
             self.config = yaml.safe_load(config_stream)
 
         # Set all of the working dirs etc to a writeable temp dir
-        temp_path = self.useFixture(fixtures.TempDir()).path
+        self.temp_path = self.useFixture(fixtures.TempDir()).path
         for config_dir in ['debug_log', 'jobs_working_dir', 'git_working_dir',
                            'pip_download_cache']:
             if config_dir in self.config:
                 if self.config[config_dir][0] == '/':
                     self.config[config_dir] = self.config[config_dir][1:]
-                self.config[config_dir] = os.path.join(temp_path,
+                self.config[config_dir] = os.path.join(self.temp_path,
                                                        self.config[config_dir])
         if self.config['publish_logs']['type'] == 'local':
             if self.config['publish_logs']['path'][0] == '/':
                 self.config['publish_logs']['path'] = \
                     self.config['publish_logs']['path'][1:]
             self.config['publish_logs']['path'] = os.path.join(
-                temp_path, self.config[config_dir])
+                self.temp_path, self.config['publish_logs']['path'])
+
+        if not os.path.isdir(
+            os.path.dirname(self.config['publish_logs']['path'])):
+            os.makedirs(os.path.dirname(self.config['publish_logs']['path']))
diff --git a/tests/etc/default-config.yaml b/tests/etc/default-config.yaml
index cfc133f..994d57f 100644
--- a/tests/etc/default-config.yaml
+++ b/tests/etc/default-config.yaml
@@ -20,13 +20,9 @@ plugins:
 
   - name: shell_script
     function: build:do_something_shelly
+    shell_script: 'ls -lah && echo'
 
 publish_logs:
-  type: swift
-  authurl: https://identity.api.rackspacecloud.com/v2.0/
-  tenant: XXXX
-  user: XXXXXX
-  password: XXXXXX
-  container: XXXXXX
-  region: SYD
-  prepend_url: http://www.rcbops.com/turbo_hipster/results/
+  type: local
+  path: /tmp/turbo-hipster/var/www/results/
+  prepend_url: http://localhost/results/
diff --git a/tests/test_shell_task.py b/tests/test_shell_task.py
new file mode 100644
index 0000000..780d0d7
--- /dev/null
+++ b/tests/test_shell_task.py
@@ -0,0 +1,231 @@
+# Copyright 2014 Rackspace Australia
+#
+# Licensed under the Apache License, Version 2.0 (the "License"); you may
+# not use this file except in compliance with the License. You may obtain
+# a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations
+# under the License.
+
+import base
+import fakes
+import json
+import logging
+import mock
+import os
+import uuid
+
+from turbo_hipster.lib.models import ShellTask, Task
+
+
+class TestTaskRunner(base.TestWithGearman):
+    log = logging.getLogger("TestTaskRunner")
+
+    def test_simple_job_passes(self):
+        self.start_server()
+        zuul = fakes.FakeZuul(self.config['zuul_server']['gearman_host'],
+                              self.config['zuul_server']['gearman_port'])
+
+        job_uuid = str(uuid.uuid1())[:8]
+        data_req = {
+            'ZUUL_UUID': job_uuid,
+            'ZUUL_PROJECT': 'stackforge/turbo-hipster',
+            'ZUUL_PIPELINE': 'check',
+            'ZUUL_URL': 'git://git.openstack.org/',
+            'BRANCH': 'master',
+            'BASE_LOG_PATH': '56/123456/8',
+            'LOG_PATH': '56/123456/8/check/job_name/%s' % job_uuid
+        }
+
+        zuul.submit_job('build:do_something_shelly', data_req)
+        zuul.wait_for_completion()
+
+        last_data = json.loads(zuul.job.data[-1])
+        self.log.debug(last_data)
+
+        self.assertTrue(zuul.job.complete)
+        self.assertFalse(zuul.job.failure)
+        self.assertEqual("SUCCESS", last_data['result'])
+
+        task_output_file = open(os.path.join(
+            self.config['publish_logs']['path'], data_req['LOG_PATH'],
+            'task_output.log'
+        ))
+
+        self.assertIn("Step 1: Setup environment", task_output_file.readline())
+
+        git_prep_file = open(os.path.join(
+            self.config['publish_logs']['path'], data_req['LOG_PATH'],
+            'git_prep.log'
+        ))
+
+        self.assertIn("gerrit-git-prep.sh", git_prep_file.readline())
+
+        shell_output_file = open(os.path.join(
+            self.config['publish_logs']['path'], data_req['LOG_PATH'],
+            'shell_output.log'
+        ))
+
+        self.assertIn("ls -lah", shell_output_file.readline())
+
+    def test_simple_job_fails(self):
+        # Test when the script fails
+        self.start_server()
+        zuul = fakes.FakeZuul(self.config['zuul_server']['gearman_host'],
+                              self.config['zuul_server']['gearman_port'])
+
+        job_uuid = str(uuid.uuid1())[:8]
+        data_req = {
+            'ZUUL_UUID': job_uuid,
+            'ZUUL_PROJECT': 'stackforge/turbo-hipster',
+            'ZUUL_PIPELINE': 'check',
+            'ZUUL_URL': 'git://git.openstack.org/',
+            'BRANCH': 'master',
+            'BASE_LOG_PATH': '56/123456/8',
+            'LOG_PATH': '56/123456/8/check/job_name/%s' % job_uuid
+        }
+
+        # Modify the job to fail. The git_path, job_working_dir and unqiue_id
+        # are all passed to the shell script. If we 'ls unique_id' it'll fail
+        # since it doesn't exist.
+        self.config['plugins'][2]['shell_script'] = 'ls -lah'
+
+        zuul.submit_job('build:do_something_shelly', data_req)
+        zuul.wait_for_completion()
+
+        last_data = json.loads(zuul.job.data[-1])
+        self.log.debug(last_data)
+
+        self.assertTrue(zuul.job.complete)
+        self.assertTrue(zuul.job.failure)
+        self.assertEqual("Return code from test script was non-zero (2)",
+                         last_data['result'])
+
+        task_output_file = open(os.path.join(
+            self.config['publish_logs']['path'], data_req['LOG_PATH'],
+            'task_output.log'
+        ))
+
+        self.assertIn("Step 1: Setup environment", task_output_file.readline())
+
+        git_prep_file = open(os.path.join(
+            self.config['publish_logs']['path'], data_req['LOG_PATH'],
+            'git_prep.log'
+        ))
+
+        self.assertIn("gerrit-git-prep.sh", git_prep_file.readline())
+
+        shell_output_file = open(os.path.join(
+            self.config['publish_logs']['path'], data_req['LOG_PATH'],
+            'shell_output.log'
+        ))
+
+        self.assertIn("ls -lah", shell_output_file.readline())
+
+    @mock.patch.object(ShellTask, '_parse_and_check_results')
+    def test_logs_uploaded_during_failure(self,
+                                          mocked_parse_and_check_results):
+        # When turbo-hipster itself fails (eg analysing results) it should
+        # still upload the python logging log if it can
+
+        def side_effect():
+            raise Exception('check results failed!')
+
+        #ShellTask._parse_and_check_results = _fake_parse_and_check_results
+        mocked_parse_and_check_results.side_effect = side_effect
+
+        self.start_server()
+        zuul = fakes.FakeZuul(self.config['zuul_server']['gearman_host'],
+                              self.config['zuul_server']['gearman_port'])
+
+        job_uuid = str(uuid.uuid1())[:8]
+        data_req = {
+            'ZUUL_UUID': job_uuid,
+            'ZUUL_PROJECT': 'stackforge/turbo-hipster',
+            'ZUUL_PIPELINE': 'check',
+            'ZUUL_URL': 'git://git.openstack.org/',
+            'BRANCH': 'master',
+            'BASE_LOG_PATH': '56/123456/8',
+            'LOG_PATH': '56/123456/8/check/job_name/%s' % job_uuid
+        }
+
+        zuul.submit_job('build:do_something_shelly', data_req)
+        zuul.wait_for_completion()
+
+        last_data = json.loads(zuul.job.data[-1])
+        self.log.debug(last_data)
+
+        self.assertTrue(zuul.job.complete)
+        self.assertTrue(zuul.job.failure)
+        self.assertEqual("FAILURE running the job\n"
+                         "Exception: check results failed!",
+                         last_data['result'])
+
+        git_prep_file = open(os.path.join(
+            self.config['publish_logs']['path'], data_req['LOG_PATH'],
+            'git_prep.log'
+        ))
+
+        self.assertIn("gerrit-git-prep.sh", git_prep_file.readline())
+
+        shell_output_file = open(os.path.join(
+            self.config['publish_logs']['path'], data_req['LOG_PATH'],
+            'shell_output.log'
+        ))
+
+        self.assertIn("ls -lah", shell_output_file.readline())
+
+        task_output_file = open(os.path.join(
+            self.config['publish_logs']['path'], data_req['LOG_PATH'],
+            'task_output.log'
+        ))
+
+        task_output_lines = task_output_file.readlines()
+        self.assertIn("Step 1: Setup environment", task_output_lines[0])
+        self.assertIn("Something failed running the job!",
+                      task_output_lines[5])
+        self.assertIn("Exception: check results failed!",
+                      task_output_lines[len(task_output_lines) - 1])
+
+    @mock.patch.object(Task, '_upload_results')
+    def test_exception_when_uploading_fails(self, mocked_upload_results):
+
+        def side_effect():
+            raise Exception('uploading results failed!')
+
+        mocked_upload_results.side_effect = side_effect
+
+        self.start_server()
+        zuul = fakes.FakeZuul(self.config['zuul_server']['gearman_host'],
+                              self.config['zuul_server']['gearman_port'])
+
+        job_uuid = str(uuid.uuid1())[:8]
+        data_req = {
+            'ZUUL_UUID': job_uuid,
+            'ZUUL_PROJECT': 'stackforge/turbo-hipster',
+            'ZUUL_PIPELINE': 'check',
+            'ZUUL_URL': 'git://git.openstack.org/',
+            'BRANCH': 'master',
+            'BASE_LOG_PATH': '56/123456/8',
+            'LOG_PATH': '56/123456/8/check/job_name/%s' % job_uuid
+        }
+
+        zuul.submit_job('build:do_something_shelly', data_req)
+        zuul.wait_for_completion()
+
+        last_data = json.loads(zuul.job.data[-1])
+        self.log.debug(last_data)
+
+        self.assertTrue(zuul.job.complete)
+        self.assertTrue(zuul.job.failure)
+        self.assertEqual("FAILURE during cleanup and log upload\n"
+                         "Exception: uploading results failed!",
+                         last_data['result'])
+
+    def test_failure_during_setup(self):
+        pass
diff --git a/tests/test_worker_manager.py b/tests/test_worker_manager.py
index 7fe2d35..f1517f5 100644
--- a/tests/test_worker_manager.py
+++ b/tests/test_worker_manager.py
@@ -40,7 +40,8 @@ class TestWorkerServer(base.TestWithGearman):
         }
         plugin2_config = {
             "name": "shell_script",
-            "function": "build:do_something_shelly"
+            "function": "build:do_something_shelly",
+            "shell_script": "ls -lah && echo",
         }
 
         self.assertEqual(plugin0_config,
diff --git a/turbo_hipster/lib/models.py b/turbo_hipster/lib/models.py
index 4da226b..3599766 100644
--- a/turbo_hipster/lib/models.py
+++ b/turbo_hipster/lib/models.py
@@ -26,7 +26,7 @@ from turbo_hipster.lib import utils
 
 class Task(object):
     """ A base object for running a job (aka Task) """
-    log = logging.getLogger("lib.models.Task")
+    log = logging.getLogger("task")
 
     def __init__(self, worker_server, plugin_config, job_name):
         self.worker_server = worker_server
@@ -37,6 +37,12 @@ class Task(object):
         # Define the number of steps we will do to determine our progress.
         self.total_steps = 0
 
+    def _cleanup(self):
+        if self.log_handler:
+            self.log.removeHandler(self.log_handler)
+            self.log_handler.flush()
+            self.log_handler.close()
+
     def _reset(self):
         self.job = None
         self.job_arguments = None
@@ -45,6 +51,36 @@ class Task(object):
         self.success = True
         self.messages = []
         self.current_step = 0
+        self.log_handler = None
+
+    def _prep_working_dir(self):
+        self.job_identifier = utils.determine_job_identifier(
+            self.job_arguments,
+            self.plugin_config['function'],
+            self.job.unique
+        )
+        self.job_working_dir = os.path.join(
+            self.worker_server.config['jobs_working_dir'],
+            self.job_identifier
+        )
+        self.job_results_dir = os.path.join(
+            self.job_working_dir,
+            'results'
+        )
+        self.task_output_log = os.path.join(
+            self.job_results_dir,
+            'task_output.log'
+        )
+
+        if not os.path.isdir(os.path.dirname(self.task_output_log)):
+            os.makedirs(os.path.dirname(self.task_output_log))
+
+    def _setup_task_logging(self):
+        self.log_handler = logging.FileHandler(self.task_output_log)
+        log_formatter = logging.Formatter('%(asctime)s %(message)s')
+        self.log_handler.setFormatter(log_formatter)
+        self.log.addHandler(self.log_handler)
+        self.log.setLevel(logging.DEBUG)
 
     def start_job(self, job):
         self._reset()
@@ -59,16 +95,54 @@ class Task(object):
                 # Send an initial WORK_DATA and WORK_STATUS packets
                 self._send_work_data()
 
+                # Prep working dirs
+                self._prep_working_dir()
+
+                # Now we have working dirs we can log the job details to a file
+                self._setup_task_logging()
+
+            except Exception as e:
+                # If something failed during this section we have been unable
+                # to log to file. As such raise an exception to gearman
+                self.log.exception("Failure during setup")
+                self.log.exception(e)
+                if not self.cancelled:
+                    self.success = False
+                    self.messages.append('FAILURE during the job setup')
+                    self.messages.append('Exception: %s' % e)
+                    self._send_work_data()
+                    self.job.sendWorkException(str(e).encode('utf-8'))
+                    # No point trying the job, lets return here
+                    return
+
+            # From here we can log exceptions
+            try:
                 # Execute the job_steps
                 self.do_job_steps()
+            except Exception as e:
+                # Log the problem
+                if not self.cancelled:
+                    self.success = False
+                    self.log.exception('Something failed running the job!')
+                    self.messages.append('FAILURE running the job')
+                    self.messages.append('Exception: %s' % e)
+                    # Don't return from here as we can continue uploading the
+                    # logs
 
+            try:
+                self._cleanup()
+                self._upload_results()
                 # Finally, send updated work data and completed packets
                 self._send_final_results()
-
             except Exception as e:
-                self.log.exception('Exception handling log event.')
+                # If something failed during this section we have been unable
+                # to upload the log. As such raise an exception to gearman
+                self.log.exception("Failure during cleanup and upload")
+                self.log.exception(e)
                 if not self.cancelled:
                     self.success = False
+                    self.messages.append('FAILURE during cleanup and log '
+                                         'upload')
                     self.messages.append('Exception: %s' % e)
                     self._send_work_data()
                     self.job.sendWorkException(str(e).encode('utf-8'))
@@ -139,24 +213,43 @@ class Task(object):
         self.current_step += 1
         self.job.sendWorkStatus(self.current_step, self.total_steps)
 
+    def _upload_results(self):
+        """Upload the contents of the working dir either using the instructions
+        provided by zuul and/or our configuration"""
+
+        self.log.debug("Process the resulting files (upload/push)")
+
+        if 'publish_logs' in self.worker_server.config:
+            index_url = utils.push_file(
+                self.job_identifier, self.job_results_dir,
+                self.worker_server.config['publish_logs'])
+            self.log.debug("Index URL found at %s" % index_url)
+            self.work_data['url'] = index_url
+
+        if 'ZUUL_EXTRA_SWIFT_URL' in self.job_arguments:
+            # Upload to zuul's url as instructed
+            utils.zuul_swift_upload(self.job_working_dir, self.job_arguments)
+            self.work_data['url'] = self.job_identifier
+
 
 class ShellTask(Task):
-    log = logging.getLogger("lib.models.ShellTask")
+    log = logging.getLogger("task.shell_task")
 
     def __init__(self, worker_server, plugin_config, job_name):
         super(ShellTask, self).__init__(worker_server, plugin_config, job_name)
         # Define the number of steps we will do to determine our progress.
-        self.total_steps = 6
+        self.total_steps = 5
 
     def _reset(self):
         super(ShellTask, self)._reset()
         self.git_path = None
         self.job_working_dir = None
         self.shell_output_log = None
+        self.git_prep_log = None
 
     def do_job_steps(self):
-        self.log.info('Step 1: Prep job working dir')
-        self._prep_working_dir()
+        self.log.info('Step 1: Setup environment')
+        self._setup_environment()
 
         self.log.info('Step 2: Checkout updates from git')
         self._grab_patchset(self.job_arguments)
@@ -167,35 +260,29 @@ class ShellTask(Task):
         self.log.info('Step 4: Analyse logs for errors')
         self._parse_and_check_results()
 
-        self.log.info('Step 5: handle the results (and upload etc)')
+        self.log.info('Step 5: handle the results')
         self._handle_results()
 
         self.log.info('Step 6: Handle extra actions such as shutting down')
         self._handle_cleanup()
 
     @common.task_step
-    def _prep_working_dir(self):
-        self.job_identifier = utils.determine_job_identifier(
-            self.job_arguments,
-            self.plugin_config['function'],
-            self.job.unique
-        )
-        self.job_working_dir = os.path.join(
-            self.worker_server.config['jobs_working_dir'],
-            self.job_identifier
+    def _setup_environment(self):
+        self.git_prep_log = os.path.join(
+            self.job_results_dir,
+            'git_prep.log'
         )
         self.shell_output_log = os.path.join(
-            self.job_working_dir,
+            self.job_results_dir,
             'shell_output.log'
         )
 
-        if not os.path.isdir(os.path.dirname(self.shell_output_log)):
-            os.makedirs(os.path.dirname(self.shell_output_log))
-
     @common.task_step
     def _grab_patchset(self, job_args):
         """ Checkout the reference into config['git_working_dir'] """
 
+        # TODO(jhesketh): Use the zuul cloner stuff instead :-)
+
         self.log.debug("Grab the patchset we want to test against")
         local_path = os.path.join(self.worker_server.config['git_working_dir'],
                                   self.job_name, job_args['ZUUL_PROJECT'])
@@ -204,11 +291,13 @@ class ShellTask(Task):
 
         git_args = copy.deepcopy(job_args)
 
-        cmd = os.path.join(os.path.join(os.path.dirname(__file__),
-                                        'gerrit-git-prep.sh'))
+        cmd = os.path.join(
+            os.path.join(os.path.dirname(os.path.abspath(__file__)),
+                         'gerrit-git-prep.sh')
+        )
         cmd += ' ' + self.worker_server.config['zuul_server']['gerrit_site']
         cmd += ' ' + self.worker_server.config['zuul_server']['git_origin']
-        utils.execute_to_log(cmd, self.shell_output_log, env=git_args,
+        utils.execute_to_log(cmd, self.git_prep_log, env=git_args,
                              cwd=local_path)
         self.git_path = local_path
         return local_path
@@ -247,28 +336,13 @@ class ShellTask(Task):
                                  '(%d)' % self.script_return_code)
 
     @common.task_step
-    def _handle_results(self):
-        """Upload the contents of the working dir either using the instructions
-        provided by zuul and/or our configuration"""
-
-        self.log.debug("Process the resulting files (upload/push)")
-
-        if 'publish_logs' in self.worker_server.config:
-            index_url = utils.push_file(
-                self.job_identifier, self.shell_output_log,
-                self.worker_server.config['publish_logs'])
-            self.log.debug("Index URL found at %s" % index_url)
-            self.work_data['url'] = index_url
-
-        if 'ZUUL_EXTRA_SWIFT_URL' in self.job_arguments:
-            # Upload to zuul's url as instructed
-            utils.zuul_swift_upload(self.job_working_dir, self.job_arguments)
-            self.work_data['url'] = self.job_identifier
-
-    @common.task_step
     def _handle_cleanup(self):
         """Handle and cleanup functions. Shutdown if requested to so that no
         further jobs are ran if the environment is dirty."""
         if ('shutdown-th' in self.plugin_config and
             self.plugin_config['shutdown-th']):
             self.worker_server.shutdown_gracefully()
+
+    @common.task_step
+    def _handle_results(self):
+        pass
diff --git a/turbo_hipster/lib/utils.py b/turbo_hipster/lib/utils.py
index 5487765..aee31e7 100644
--- a/turbo_hipster/lib/utils.py
+++ b/turbo_hipster/lib/utils.py
@@ -232,17 +232,27 @@ def swift_push_file(results_set_name, file_path, swift_config):
 
 def local_push_file(results_set_name, file_path, local_config):
     """ Copy the file locally somewhere sensible """
-    dest_dir = os.path.join(local_config['path'], results_set_name)
-    dest_filename = os.path.basename(file_path)
-    if not os.path.isdir(dest_dir):
-        os.makedirs(dest_dir)
+    def _push_file_or_dir(results_set_name, file_path, local_config):
+        dest_dir = os.path.join(local_config['path'], results_set_name)
+        dest_filename = os.path.basename(file_path)
+        if not os.path.isdir(dest_dir):
+            os.makedirs(dest_dir)
+
+        dest_file = os.path.join(dest_dir, dest_filename)
 
-    dest_file = os.path.join(dest_dir, dest_filename)
+        if os.path.isfile(file_path):
+            shutil.copyfile(file_path, dest_file)
+        elif os.path.isdir(file_path):
+            shutil.copytree(file_path, dest_file)
 
     if os.path.isfile(file_path):
-        shutil.copyfile(file_path, dest_file)
+        _push_file_or_dir(results_set_name, file_path, local_config)
     elif os.path.isdir(file_path):
-        shutil.copytree(file_path, dest_file)
+        for f in os.listdir(file_path):
+            f_path = os.path.join(file_path, f)
+            _push_file_or_dir(results_set_name, f_path, local_config)
+
+    dest_filename = os.path.basename(file_path)
     return local_config['prepend_url'] + os.path.join(results_set_name,
                                                       dest_filename)
 
diff --git a/turbo_hipster/task_plugins/real_db_upgrade/task.py b/turbo_hipster/task_plugins/real_db_upgrade/task.py
index 252160a..635566c 100644
--- a/turbo_hipster/task_plugins/real_db_upgrade/task.py
+++ b/turbo_hipster/task_plugins/real_db_upgrade/task.py
@@ -38,7 +38,7 @@ class Runner(models.ShellTask):
         It pulls in a gearman job from the  build:real-db-upgrade
         queue and runs it through _handle_patchset"""
 
-    log = logging.getLogger("task_plugins.real_db_upgrade.task.Runner")
+    log = logging.getLogger("task.real_db_upgrade")
 
     def __init__(self, worker_server, plugin_config, job_name):
         super(Runner, self).__init__(worker_server, plugin_config, job_name)