x/turbo-hipster
Code Issues Proposed changes

Improve how jobs log

Browse Source 
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
This commit is contained in:
Joshua Hesketh 2014-10-29 17:42:59 +11:00
parent 3e3deef7b8
commit d5d7a21ed0
8 changed files with 385 additions and 66 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

3
test-requirements.txt
View File

@ -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

10
tests/base.py
View File

@ -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']))

12
tests/etc/default-config.yaml
View File

@ -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/

231
tests/test_shell_task.py Normal file
View File

@ -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

3
tests/test_worker_manager.py
View File

@ -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,

166
turbo_hipster/lib/models.py
View File

@ -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()
# Execute the job_steps
self.do_job_steps()
# Prep working dirs
self._prep_working_dir()
# Finally, send updated work data and completed packets
self._send_final_results()
# Now we have working dirs we can log the job details to a file
self._setup_task_logging()
except Exception as e:
self.log.exception('Exception handling log event.')
# 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:
# 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
@ -246,25 +335,6 @@ class ShellTask(Task):
self.messages.append('Return code from test script was non-zero '
'(%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
@ -272,3 +342,7 @@ class ShellTask(Task):
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

24
turbo_hipster/lib/utils.py
View File

@ -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)

2
turbo_hipster/task_plugins/real_db_upgrade/task.py
View File

@ -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)