From 4e1922737c2fec5d64aea2f6b831f01799623f0f Mon Sep 17 00:00:00 2001 From: Ed Cranford Date: Mon, 30 Jun 2014 12:28:41 -0500 Subject: [PATCH] Configurable build-app and unittest logs Output from those stages is in a JSON format as set forth in the stage-logs spec. Change-Id: I050d8ed0d49ca3679ea62b8d6ee4165f227193ba --- contrib/lp-cedarish/docker/app-common | 57 ++++++++++++++++--- contrib/lp-cedarish/docker/build-app | 30 ++++++++-- contrib/lp-cedarish/docker/unittest-app | 32 +++++++++-- etc/solum/solum.conf.sample | 3 + examples/plans/solum-pep8.yaml | 10 ++++ solum/api/controllers/v1/datamodel/plan.py | 3 + solum/api/handlers/assembly_handler.py | 4 +- solum/conductor/handlers/default.py | 2 +- solum/tests/worker/handlers/test_shell.py | 31 ++++++---- .../worker/handlers/test_shell_nobuild.py | 9 +-- solum/worker/config.py | 3 + solum/worker/handlers/shell.py | 23 +++++++- 12 files changed, 169 insertions(+), 38 deletions(-) create mode 100644 examples/plans/solum-pep8.yaml diff --git a/contrib/lp-cedarish/docker/app-common b/contrib/lp-cedarish/docker/app-common index 4099b1bd2..cec6559e6 100644 --- a/contrib/lp-cedarish/docker/app-common +++ b/contrib/lp-cedarish/docker/app-common @@ -1,18 +1,60 @@ #!/bin/bash +# Copyright 2014 - Rackspace Hosting +# +# 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. + + # Common functions for build-app and unittest-app # Add a timestamp, and log a message to STDOUT and to $LOG. function TLOG () { local MESSAGE="$*" - local LOGFILE=${LOG:-/dev/null} - local TIMESTAMP=`date +"%Y-%m-%d %H:%M:%S.%3N"` - echo "$TIMESTAMP | $MESSAGE" | tee -a $LOGFILE + if [ ! -z "$MESSAGE" ]; then + local LOGFILE=${LOG_FILE:-/dev/null} + local TIMESTAMP=$(date +"%Y-%m-%d %H:%M:%S.%3N") + echo "$TIMESTAMP | $MESSAGE" + cat << EOF >> $LOGFILE +{ "@timestamp": "$TIMESTAMP", + "project_id": "$PROJECT_ID", + "build_id": "$BUILD_ID", + "task": "$TASKNAME", + "message": "$MESSAGE", +} +EOF + fi +} + +# Build the logfile name, and ensure it exists. +function GET_LOGFILE () { + local LOG_DIR=${SOLUM_TASK_DIR:-/dev/null} + if [ "$LOG_DIR" != "/dev/null" ]; then + sudo mkdir -p "$LOG_DIR" + sudo chmod a+w "$LOG_DIR" + fi + + local LOG_FILE=/dev/null + if [ "$LOG_DIR" != "/dev/null" ]; then + LOG_FILE="$LOG_DIR/$BUILD_ID.log" + touch $LOG_FILE + fi + + echo $LOG_FILE } # Get time elapsed since $1. function elapsed () { local START=$1 - local NOW=`date +'%s'` + local NOW=$(date +"%s") expr $NOW - $START } @@ -25,7 +67,7 @@ function PRUN () { shift fi - local CMD="$@" + local CMD="$*" local LOGFILE=${LOG:-/dev/null} if $SILENT; then @@ -36,12 +78,13 @@ function PRUN () { TLOG Starting: $CMD fi local EXIT_STATUS - local START=`date +'%s'` + local START=$(date +"%s") if $SILENT; then $CMD 2>&1 >> /dev/null; test ${PIPESTATUS[0]} -eq 0 EXIT_STATUS=$? else - $CMD 2>&1 | tee -a $LOGFILE; test ${PIPESTATUS[0]} -eq 0 + TLOG Starting: $CMD + $CMD 2>&1 > >(while read LINE; do TLOG $LINE; done) EXIT_STATUS=$? fi diff --git a/contrib/lp-cedarish/docker/build-app b/contrib/lp-cedarish/docker/build-app index c21719992..410f6ef2c 100755 --- a/contrib/lp-cedarish/docker/build-app +++ b/contrib/lp-cedarish/docker/build-app @@ -1,14 +1,34 @@ #!/bin/bash -# Solum Build Scirpt for Docker and lp-cedarish +# Copyright 2014 - Rackspace Hosting +# +# 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. -SCRIPT_START_TIME=`date +'%s'` -LOG=${SOLUM_BUILD_LOG:="/opt/stack/logs/solum_build.log"} + +# Solum Build Script for Docker and lp-cedarish + +SCRIPT_START_TIME=$(date +"%s") + +PROJECT_ID=${PROJECT_ID:-null} +BUILD_ID=${BUILD_ID:-null} +TASKNAME=build REUSE_IMAGES_IF_REPO_UNCHANGED=${REUSE_IMAGES_IF_REPO_UNCHANGED:="1"} -# TLOG, PRUN, and elapsed defined in app-common +# TLOG, PRUN, ENSURE_LOGFILE, and elapsed defined in app-common HERE=$(dirname $0) source $HERE/app-common +LOG_FILE=$(GET_LOGFILE) + # Get the image_id of the image named $1 function app_glance_id () { glance image-list --name $1 --sort-key updated_at --sort-dir asc | grep -v "+--" | tail -1 | cut -d'|' -f2 @@ -48,7 +68,7 @@ shift BASE_DIR=/dev/shm GIT_CHECKSUM=$(echo $GIT | md5sum | awk '{print $1;}') APP_DIR=$BASE_DIR/apps/$TENANT/$GIT_CHECKSUM -PRUN mkdir -p $APP_DIR +PRUN silent mkdir -p $APP_DIR if [ -d "$APP_DIR/build" ] ; then cd $APP_DIR/build diff --git a/contrib/lp-cedarish/docker/unittest-app b/contrib/lp-cedarish/docker/unittest-app index a11f1ca0d..251c64f2b 100755 --- a/contrib/lp-cedarish/docker/unittest-app +++ b/contrib/lp-cedarish/docker/unittest-app @@ -1,13 +1,33 @@ #!/bin/bash +# Copyright 2014 - Rackspace Hosting +# +# 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. + + # Solum App Unit Test Script for Docker -SCRIPT_START_TIME=`date +'%s'` -LOG=${SOLUM_UNITTEST_LOG:="/opt/stack/logs/solum_unittest.log"} +SCRIPT_START_TIME=$(date +"%s") -# TLOG, PRUN, and elapsed defined in app-common +PROJECT_ID=${PROJECT_ID:-null} +BUILD_ID=${BUILD_ID:-null} +TASKNAME=unittest + +# TLOG, PRUN, ENSURE_LOGFILE, and elapsed defined in app-common HERE=$(dirname $0) source $HERE/app-common +LOG_FILE=$(GET_LOGFILE) + TLOG ===== Starting Test Script $0 $* # Make sure tenant auth credentials were passed in @@ -35,16 +55,16 @@ shift ENTRYPOINT="$@" shift -echo "Executing test command $ENTRYPOINT" +TLOG "Executing test command $ENTRYPOINT" DOCKER_REGISTRY=${DOCKER_REGISTRY:-'127.0.0.1:5042'} # Test the application code TLOG "===>" Testing App -sudo docker run --rm -e "GIT_URL=$GIT" -e "GIT_BRANCH=$GIT_BRANCH" -e "TEST_CMD=$ENTRYPOINT" $DOCKER_REGISTRY/slugtester +sudo docker run --rm -e GIT_URL=$GIT -e TEST_CMD="$ENTRYPOINT" $DOCKER_REGISTRY/slugtester 2>&1 > >(while read LINE; do TLOG $LINE; done) SUCCESS=$? -echo Docker finished with status $SUCCESS. +TLOG Docker finished with status $SUCCESS. TOTAL_TIME=$(elapsed $SCRIPT_START_TIME) TLOG ===== Total elapsed time: $TOTAL_TIME sec diff --git a/etc/solum/solum.conf.sample b/etc/solum/solum.conf.sample index 6702010d9..e9101a11a 100644 --- a/etc/solum/solum.conf.sample +++ b/etc/solum/solum.conf.sample @@ -808,4 +808,7 @@ # The worker endpoint to employ (string value) #handler=shell +# The directory containing task log output. (string value) +#task_log_dir=/var/log/solum/worker + diff --git a/examples/plans/solum-pep8.yaml b/examples/plans/solum-pep8.yaml new file mode 100644 index 000000000..a90d4028d --- /dev/null +++ b/examples/plans/solum-pep8.yaml @@ -0,0 +1,10 @@ +version: 1 +name: solum8 +description: solum with pep8 +artifacts: +- name: solum8 + artifact_type: heroku + content: + href: https://github.com/stackforge/solum.git + language_pack: auto + unittest_cmd: tox -epep8 diff --git a/solum/api/controllers/v1/datamodel/plan.py b/solum/api/controllers/v1/datamodel/plan.py index fba2ee9f3..c0cb1750a 100644 --- a/solum/api/controllers/v1/datamodel/plan.py +++ b/solum/api/controllers/v1/datamodel/plan.py @@ -60,6 +60,9 @@ class Artifact(wtypes.Base): requirements = [Requirement] "List of requirements for the artifact." + unittest_cmd = wtypes.text + "Optional unit test command for the artifact." + def __init__(self, **kwargs): if 'requirements' in kwargs: kwargs['requirements'] = [Requirement(**re) diff --git a/solum/api/handlers/assembly_handler.py b/solum/api/handlers/assembly_handler.py index 477ebcfe0..267416b33 100644 --- a/solum/api/handlers/assembly_handler.py +++ b/solum/api/handlers/assembly_handler.py @@ -127,7 +127,7 @@ class AssemblyHandler(handler.Handler): def _unittest_artifact(self, assem, artifact): git_url = artifact['content']['href'] - test_cmd = artifact['content'].get('unittest_cmd') + test_cmd = artifact.get('unittest_cmd') api.API(context=self.context).unittest( assembly_id=assem.id, @@ -149,7 +149,7 @@ class AssemblyHandler(handler.Handler): image.project_id = self.context.tenant image.state = IMAGE_STATES.PENDING image.create(self.context) - test_cmd = artifact['content'].get('unittest_cmd', None) + test_cmd = artifact.get('unittest_cmd') api.API(context=self.context).build( build_id=image.id, diff --git a/solum/conductor/handlers/default.py b/solum/conductor/handlers/default.py index f9d935ae5..6c22f3d77 100644 --- a/solum/conductor/handlers/default.py +++ b/solum/conductor/handlers/default.py @@ -45,7 +45,7 @@ class Handler(object): assembly_id) if not any([comp for comp in assem.components if 'Image_Build' in comp.description]): - comp_name = 'Heat_Stack_for_%s' % assem.name + comp_name = "Heat_Stack_for_%s" % assem.name stack_id = None if assem.heat_stack_component is not None: stack_id = assem.heat_stack_component.heat_stack_id diff --git a/solum/tests/worker/handlers/test_shell.py b/solum/tests/worker/handlers/test_shell.py index a48a73cb1..66580d690 100644 --- a/solum/tests/worker/handlers/test_shell.py +++ b/solum/tests/worker/handlers/test_shell.py @@ -24,6 +24,15 @@ from solum.tests import utils from solum.worker.handlers import shell as shell_handler +def mock_environment(): + return { + 'PATH': '/bin', + 'SOLUM_TASK_DIR': '/dev/null', + 'BUILD_ID': 'abcd', + 'PROJECT_ID': 1, + } + + class HandlerTest(base.BaseTestCase): def setUp(self): super(HandlerTest, self).setUp() @@ -48,7 +57,7 @@ class HandlerTest(base.BaseTestCase): handler._update_assembly_status = mock.MagicMock() mock_popen.return_value.communicate.return_value = [ 'foo\ncreated_image_id=%s' % fake_glance_id, None] - test_env = {'PATH': '/bin'} + test_env = mock_environment() mock_get_env.return_value = test_env handler.build(self.ctx, 5, 'git://example.com/foo', 'new_app', '1-2-3-4', 'heroku', @@ -82,7 +91,7 @@ class HandlerTest(base.BaseTestCase): handler._update_assembly_status = mock.MagicMock() mock_popen.return_value.communicate.return_value = [ 'foo\ncreated_image_id= \n', None] - test_env = {'PATH': '/bin'} + test_env = mock_environment() mock_get_env.return_value = test_env handler.build(self.ctx, 5, 'git://example.com/foo', 'new_app', '1-2-3-4', 'heroku', @@ -109,7 +118,7 @@ class HandlerTest(base.BaseTestCase): handler = shell_handler.Handler() fake_assembly = fakes.FakeAssembly() mock_registry.Assembly.get_by_id.return_value = fake_assembly - test_env = {'PATH': '/bin'} + test_env = mock_environment() mock_get_env.return_value = test_env mock_popen.return_value.wait.return_value = 0 handler.unittest(self.ctx, fake_assembly.id, @@ -121,7 +130,7 @@ class HandlerTest(base.BaseTestCase): 'contrib/lp-cedarish/docker/unittest-app') mock_popen.assert_called_once_with([script, 'git://example.com/foo', 'master', self.ctx.tenant, 'tox'], - env=test_env) + env=test_env, stdout=-1) expected = [mock.call(self.ctx, 8, 'UNIT_TESTING')] self.assertEqual(expected, mock_a_update.call_args_list) @@ -135,7 +144,7 @@ class HandlerTest(base.BaseTestCase): handler = shell_handler.Handler() fake_assembly = fakes.FakeAssembly() mock_registry.Assembly.get_by_id.return_value = fake_assembly - test_env = {'PATH': '/bin'} + test_env = mock_environment() mock_get_env.return_value = test_env mock_popen.return_value.wait.return_value = 1 handler.unittest(self.ctx, fake_assembly.id, @@ -147,7 +156,7 @@ class HandlerTest(base.BaseTestCase): 'contrib/lp-cedarish/docker/unittest-app') mock_popen.assert_called_once_with([script, 'git://example.com/foo', 'master', self.ctx.tenant, 'tox'], - env=test_env) + env=test_env, stdout=-1) expected = [mock.call(self.ctx, 8, 'UNIT_TESTING'), mock.call(self.ctx, 8, 'UNIT_TESTING_FAILED')] @@ -171,7 +180,7 @@ class HandlerTest(base.BaseTestCase): mock_popen.return_value.wait.return_value = 0 mock_popen.return_value.communicate.return_value = [ 'foo\ncreated_image_id=%s' % fake_glance_id, None] - test_env = {'PATH': '/bin'} + test_env = mock_environment() mock_get_env.return_value = test_env handler.build(self.ctx, 5, 'git://example.com/foo', 'new_app', @@ -186,9 +195,9 @@ class HandlerTest(base.BaseTestCase): expected = [ mock.call([u_script, 'git://example.com/foo', 'master', - self.ctx.tenant, 'faketests'], env=test_env), + self.ctx.tenant, 'faketests'], env=test_env, stdout=-1), mock.call([b_script, 'git://example.com/foo', 'new_app', - self.ctx.tenant, '1-2-3-4'], stdout=-1, env=test_env)] + self.ctx.tenant, '1-2-3-4'], env=test_env, stdout=-1)] self.assertEqual(expected, mock_popen.call_args_list) expected = [mock.call(5, 'BUILDING', 'Starting the image build', @@ -211,7 +220,7 @@ class HandlerTest(base.BaseTestCase): handler = shell_handler.Handler() handler._update_assembly_status = mock.MagicMock() mock_popen.return_value.wait.return_value = 1 - test_env = {'PATH': '/bin'} + test_env = mock_environment() mock_get_env.return_value = test_env handler.build(self.ctx, 5, 'git://example.com/foo', 'new_app', @@ -225,7 +234,7 @@ class HandlerTest(base.BaseTestCase): expected = [ mock.call([u_script, 'git://example.com/foo', 'master', - self.ctx.tenant, 'faketests'], env=test_env)] + self.ctx.tenant, 'faketests'], env=test_env, stdout=-1)] self.assertEqual(expected, mock_popen.call_args_list) expected = [mock.call(self.ctx, 44, 'UNIT_TESTING'), diff --git a/solum/tests/worker/handlers/test_shell_nobuild.py b/solum/tests/worker/handlers/test_shell_nobuild.py index 31c6d515a..c7655cd76 100644 --- a/solum/tests/worker/handlers/test_shell_nobuild.py +++ b/solum/tests/worker/handlers/test_shell_nobuild.py @@ -20,6 +20,7 @@ import mock from solum.tests import base from solum.tests import fakes from solum.tests import utils +from solum.tests.worker.handlers import test_shell from solum.worker.handlers import shell_nobuild as shell_handler @@ -46,7 +47,7 @@ class HandlerTest(base.BaseTestCase): mock_popen.return_value.wait.return_value = 0 mock_popen.return_value.communicate.return_value = [ 'foo\ncreated_image_id=%s' % fake_glance_id, None] - test_env = {'PATH': '/bin'} + test_env = test_shell.mock_environment() mock_get_env.return_value = test_env handler.build(self.ctx, 5, 'git://example.com/foo', 'new_app', @@ -60,7 +61,7 @@ class HandlerTest(base.BaseTestCase): expected = [ mock.call([u_script, 'git://example.com/foo', 'master', - self.ctx.tenant, 'faketests'], env=test_env)] + self.ctx.tenant, 'faketests'], env=test_env, stdout=-1)] self.assertEqual(expected, mock_popen.call_args_list) # The UNIT_TESTING update happens from shell... @@ -84,7 +85,7 @@ class HandlerTest(base.BaseTestCase): mock_registry.Assembly.get_by_id.return_value = fake_assembly mock_popen.return_value.wait.return_value = 1 - test_env = {'PATH': '/bin'} + test_env = test_shell.mock_environment() mock_get_env.return_value = test_env handler.build(self.ctx, 5, 'git://example.com/foo', 'new_app', @@ -98,7 +99,7 @@ class HandlerTest(base.BaseTestCase): expected = [ mock.call([u_script, 'git://example.com/foo', 'master', - self.ctx.tenant, 'faketests'], env=test_env)] + self.ctx.tenant, 'faketests'], env=test_env, stdout=-1)] self.assertEqual(expected, mock_popen.call_args_list) expected = [mock.call(self.ctx, 44, 'UNIT_TESTING'), diff --git a/solum/worker/config.py b/solum/worker/config.py index 95b0418e4..217f9d4f6 100644 --- a/solum/worker/config.py +++ b/solum/worker/config.py @@ -27,6 +27,9 @@ SERVICE_OPTS = [ cfg.StrOpt('handler', default='shell', help='The worker endpoint to employ'), + cfg.StrOpt('task_log_dir', + default='/var/log/solum/worker', + help='The directory containing task log output.'), ] opt_group = cfg.OptGroup( diff --git a/solum/worker/handlers/shell.py b/solum/worker/handlers/shell.py index 68e13313d..9a226978f 100644 --- a/solum/worker/handlers/shell.py +++ b/solum/worker/handlers/shell.py @@ -17,6 +17,8 @@ import os import subprocess +from oslo.config import cfg + import solum from solum.common import exception from solum.common import solum_keystoneclient @@ -32,6 +34,8 @@ LOG = logging.getLogger(__name__) ASSEMBLY_STATES = assembly.States IMAGE_STATES = image.States +cfg.CONF.import_opt('task_log_dir', 'solum.worker.config', group='worker') + def job_update_notification(ctxt, build_id, state=None, description=None, created_image_id=None, assembly_id=None): @@ -74,6 +78,11 @@ class Handler(object): user_env['OS_AUTH_TOKEN'] = ctxt.auth_token user_env['OS_AUTH_URL'] = ctxt.auth_url user_env['OS_IMAGE_URL'] = image_url + + user_env['PROJECT_ID'] = ctxt.tenant + + user_env['BUILD_ID'] = uuidutils.generate_uuid() + user_env['SOLUM_TASK_DIR'] = cfg.CONF.worker.task_log_dir return user_env @property @@ -134,6 +143,10 @@ class Handler(object): job_update_notification(ctxt, build_id, IMAGE_STATES.BUILDING, description='Starting the image build', assembly_id=assembly_id) + # TODO(datsun180b): Associate log with assembly properly + logpath = "%s/%s.log" % (user_env['SOLUM_TASK_DIR'], + user_env['BUILD_ID']) + LOG.debug("Build logs stored at %s" % logpath) try: out = subprocess.Popen(build_cmd, env=user_env, @@ -143,6 +156,7 @@ class Handler(object): job_update_notification(ctxt, build_id, IMAGE_STATES.ERROR, description=subex, assembly_id=assembly_id) return + # we expect one line in the output that looks like: # created_image_id= created_image_id = None @@ -159,7 +173,7 @@ class Handler(object): description='built successfully', created_image_id=created_image_id, assembly_id=assembly_id) - if assembly_id is not None: + if created_image_id is not None: deployer_api.API(context=ctxt).deploy(assembly_id=assembly_id, image_id=created_image_id) @@ -186,9 +200,14 @@ class Handler(object): del log_env['OS_AUTH_TOKEN'] solum.TLS.trace.support_info(environment=log_env) + logpath = "%s/%s.log" % (user_env['SOLUM_TASK_DIR'], + user_env['BUILD_ID']) + LOG.debug("Unittest logs stored at %s" % logpath) + returncode = -1 try: - runtest = subprocess.Popen(command, env=user_env) + runtest = subprocess.Popen(command, env=user_env, + stdout=subprocess.PIPE) returncode = runtest.wait() except OSError as subex: LOG.exception("Exception running unit tests:")