Merge "Log all resource events during overcloud deploy"

requirements.txt

@@ -9,7 +9,7 @@ ipaddress
 passlib>=1.6
 python-ironic-inspector-client>=1.0.1
 os-cloud-config
-python-heatclient>=0.3.0
+python-heatclient>=0.6.0
 python-ironicclient>=0.8.0
 python-openstackclient>=1.5.0
 six>=1.9.0

tripleoclient/tests/test_utils.py

@@ -115,19 +115,36 @@ class TestCheckHypervisorUtil(TestCase):
 class TestWaitForStackUtil(TestCase):
     def setUp(self):
         self.mock_orchestration = mock.Mock()
-        self.mock_stacks = mock.MagicMock()
-        self.stack_status = mock.PropertyMock()
-        type(self.mock_stacks).stack_status = self.stack_status
-        self.mock_orchestration.stacks.get.return_value = self.mock_stacks
 
+    def mock_event(self, resource_name, id, resource_status_reason,
+                   resource_status, event_time):
+        e = mock.Mock()
+        e.resource_name = resource_name
+        e.id = id
+        e.resource_status_reason = resource_status_reason
+        e.resource_status = resource_status
+        e.event_time = event_time
+        return e
+
+    @mock.patch("heatclient.common.event_utils.get_events")
     @mock.patch('time.sleep', return_value=None)
-    def test_wait_for_stack_ready(self, sleep_mock):
+    def test_wait_for_stack_ready(self, sleep_mock, mock_el):
-        self.mock_orchestration.reset_mock()
+        stack = mock.Mock()
-        self.mock_stacks.reset_mock()
+        stack.stack_name = 'stack'
+        self.mock_orchestration.stacks.get.return_value = stack
 
-        return_values = ['CREATE_IN_PROGRESS', 'CREATE_COMPLETE']
+        mock_el.side_effect = [[
-
+            self.mock_event('stack', 'aaa', 'Stack CREATE started',
-        self.stack_status.side_effect = return_values
+                            'CREATE_IN_PROGRESS', '2015-10-14T02:25:21Z'),
+            self.mock_event('thing', 'bbb', 'state changed',
+                            'CREATE_IN_PROGRESS', '2015-10-14T02:25:21Z'),
+        ], [
+            self.mock_event('thing', 'ccc', 'state changed',
+                            'CREATE_COMPLETE', '2015-10-14T02:25:43Z'),
+            self.mock_event('stack', 'ddd',
+                            'Stack CREATE completed successfully',
+                            'CREATE_COMPLETE', '2015-10-14T02:25:43Z'),
+        ]]
 
         complete = utils.wait_for_stack_ready(self.mock_orchestration, 'stack')
 
@@ -136,28 +153,36 @@ class TestWaitForStackUtil(TestCase):
         sleep_mock.assert_called_once_with(mock.ANY)
 
     def test_wait_for_stack_ready_no_stack(self):
-        self.mock_orchestration.reset_mock()
-
         self.mock_orchestration.stacks.get.return_value = None
 
         complete = utils.wait_for_stack_ready(self.mock_orchestration, 'stack')
 
-        self.mock_orchestration.stacks.get.return_value = self.mock_stacks
-
         self.assertFalse(complete)
 
-    def test_wait_for_stack_ready_failed(self):
+    @mock.patch("heatclient.common.event_utils.get_events")
-        self.mock_orchestration.reset_mock()
+    @mock.patch('time.sleep', return_value=None)
-        self.mock_stacks.reset_mock()
+    def test_wait_for_stack_ready_failed(self, sleep_mock, mock_el):
-
+        stack = mock.Mock()
-        return_values = ['CREATE_FAILED']
+        stack.stack_name = 'stack'
-
+        self.mock_orchestration.stacks.get.return_value = stack
-        self.stack_status.side_effect = return_values
+        mock_el.side_effect = [[
+            self.mock_event('stack', 'aaa', 'Stack CREATE started',
+                            'CREATE_IN_PROGRESS', '2015-10-14T02:25:21Z'),
+            self.mock_event('thing', 'bbb', 'state changed',
+                            'CREATE_IN_PROGRESS', '2015-10-14T02:25:21Z'),
+        ], [
+            self.mock_event('thing', 'ccc', 'ouch',
+                            'CREATE_FAILED', '2015-10-14T02:25:43Z'),
+            self.mock_event('stack', 'ddd', 'ouch',
+                            'CREATE_FAILED', '2015-10-14T02:25:43Z'),
+        ]]
 
         complete = utils.wait_for_stack_ready(self.mock_orchestration, 'stack')
 
         self.assertFalse(complete)
 
+        sleep_mock.assert_called_once_with(mock.ANY)
+
 
 class TestWaitForIntrospection(TestCase):
 

tripleoclient/tests/v1/overcloud_deploy/test_overcloud_deploy.py

@@ -35,7 +35,9 @@ class TestDeployOvercloud(fakes.TestDeployOvercloud):
         super(TestDeployOvercloud, self).setUp()
 
         # Get the command object to test
-        self.cmd = overcloud_deploy.DeployOvercloud(self.app, None)
+        app_args = mock.Mock()
+        app_args.verbose_level = 1
+        self.cmd = overcloud_deploy.DeployOvercloud(self.app, app_args)
 
         # mock validations for all deploy tests
         # for validator tests, see test_overcloud_deploy_validators.py
@@ -51,6 +53,7 @@ class TestDeployOvercloud(fakes.TestDeployOvercloud):
         super(TestDeployOvercloud, self).tearDown()
         os.unlink(self.parameter_defaults_env_file)
 
+    @mock.patch("heatclient.common.event_utils.get_events")
     @mock.patch('tripleo_common.update.add_breakpoints_cleanup_into_env')
     @mock.patch('tripleoclient.v1.overcloud_deploy.DeployOvercloud.'
                 '_create_parameters_env')
@@ -93,7 +96,8 @@ class TestDeployOvercloud(fakes.TestDeployOvercloud):
                        mock_create_tempest_deployer_input,
                        mock_deploy_postconfig,
                        mock_create_parameters_env,
-                       mock_breakpoints_cleanup):
+                       mock_breakpoints_cleanupm,
+                       mock_events):
 
         arglist = ['--templates', '--ceph-storage-scale', '3']
         verifylist = [
@@ -109,6 +113,9 @@ class TestDeployOvercloud(fakes.TestDeployOvercloud):
         clients = self.app.client_manager
         orchestration_client = clients.tripleoclient.orchestration
         orchestration_client.stacks.get.return_value = fakes.create_tht_stack()
+        mock_event = mock.Mock()
+        mock_event.id = '1234'
+        mock_events.return_value = [mock_events]
 
         mock_check_hypervisor_stats.return_value = {
             'count': 4,
@@ -372,6 +379,7 @@ class TestDeployOvercloud(fakes.TestDeployOvercloud):
 
         mock_validate_args.assert_called_once_with(parsed_args)
 
+    @mock.patch("heatclient.common.event_utils.get_events")
     @mock.patch('tripleo_common.update.add_breakpoints_cleanup_into_env')
     @mock.patch('tripleoclient.v1.overcloud_deploy.DeployOvercloud.'
                 '_deploy_postconfig')
@@ -409,7 +417,8 @@ class TestDeployOvercloud(fakes.TestDeployOvercloud):
                                      mock_generate_overcloud_passwords,
                                      mock_create_tempest_deployer_input,
                                      mock_deploy_postconfig,
-                                     mock_breakpoints_cleanup):
+                                     mock_breakpoints_cleanup,
+                                     mock_events):
 
         arglist = ['--templates', '/home/stack/tripleo-heat-templates']
         verifylist = [
@@ -421,6 +430,8 @@ class TestDeployOvercloud(fakes.TestDeployOvercloud):
         clients = self.app.client_manager
         orchestration_client = clients.tripleoclient.orchestration
         orchestration_client.stacks.get.return_value = fakes.create_tht_stack()
+        orchestration_client.stacks.get.return_value = fakes.create_tht_stack()
+        mock_events.return_value = []
 
         mock_check_hypervisor_stats.return_value = {
             'count': 4,

tripleoclient/utils.py

@@ -19,13 +19,13 @@ import json
 import logging
 import os
 import passlib.utils as passutils
-import re
 import six
 import struct
 import subprocess
 import sys
 import time
 
+from heatclient.common import event_utils
 from heatclient.exc import HTTPNotFound
 from six.moves import configparser
 from six.moves import urllib
@@ -176,7 +176,8 @@ def check_hypervisor_stats(compute_client, nodes=1, memory=0, vcpu=0):
         return None
 
 
-def wait_for_stack_ready(orchestration_client, stack_name):
+def wait_for_stack_ready(orchestration_client, stack_name, marker=None,
+                         action='CREATE', verbose=False):
     """Check the status of an orchestration stack
 
     Get the status of an orchestration stack and check whether it is complete
@@ -187,26 +188,63 @@ def wait_for_stack_ready(orchestration_client, stack_name):
 
     :param stack_name: Name or UUID of stack to retrieve
     :type  stack_name: string
+
+    :param marker: UUID of the last stack event before the current action
+    :type  marker: string
+
+    :param action: Current action to check the stack for COMPLETE
+    :type action: string
+
+    :param verbose: Whether to print events
+    :type verbose: boolean
     """
-    SUCCESSFUL_MATCH_OUTPUT = "(CREATE|UPDATE)_COMPLETE"
+    stack = get_stack(orchestration_client, stack_name)
-    FAIL_MATCH_OUTPUT = "(CREATE|UPDATE)_FAILED"
+    if not stack:
+        return False
+    stack_name = stack.stack_name
 
     while True:
-        stack = orchestration_client.stacks.get(stack_name)
+        events = event_utils.get_events(orchestration_client,
+                                        stack_id=stack_name, nested_depth=2,
+                                        event_args={'sort_dir': 'asc',
+                                                    'marker': marker})
 
-        if not stack:
+        if len(events) >= 1:
-            return False
+            # set marker to last event that was received.
+            marker = getattr(events[-1], 'id', None)
 
-        status = stack.stack_status
+            if verbose:
+                events_log = event_log_formatter(events)
+                print(events_log)
+            for event in events:
+                # check if stack event was also received
+                if getattr(event, 'resource_name', '') == stack_name:
+                    stack_status = getattr(event, 'resource_status', '')
+                    print("Stack %(name)s %(status)s" % dict(
+                        name=stack_name, status=stack_status))
+                    if stack_status == '%s_COMPLETE' % action:
+                        return True
+                    elif stack_status == '%s_FAILED' % action:
+                        return False
+        time.sleep(5)
 
-        if re.match(SUCCESSFUL_MATCH_OUTPUT, status):
-            return True
-        if re.match(FAIL_MATCH_OUTPUT, status):
-            print("Stack failed with status: {}".format(
-                stack.stack_status_reason, file=sys.stderr))
-            return False
 
-        time.sleep(10)
+def event_log_formatter(events):
+    """Return the events in log format."""
+    event_log = []
+    log_format = ("%(event_time)s "
+                  "[%(rsrc_name)s]: %(rsrc_status)s  %(rsrc_status_reason)s")
+    for event in events:
+        event_time = getattr(event, 'event_time', '')
+        log = log_format % {
+            'event_time': event_time.replace('T', ' '),
+            'rsrc_name': getattr(event, 'resource_name', ''),
+            'rsrc_status': getattr(event, 'resource_status', ''),
+            'rsrc_status_reason': getattr(event, 'resource_status_reason', '')
+        }
+        event_log.append(log)
+
+    return "\n".join(event_log)
 
 
 def wait_for_provision_state(baremetal_client, node_uuid, provision_state,

tripleoclient/v1/overcloud_deploy.py

@@ -27,6 +27,7 @@ import time
 import uuid
 
 from cliff import command
+from heatclient.common import event_utils
 from heatclient.common import template_utils
 from keystoneclient import exceptions as kscexc
 from openstackclient.common import exceptions as oscexc
@@ -254,15 +255,26 @@ class DeployOvercloud(command.Command):
 
         if stack is None:
             self.log.info("Performing Heat stack create")
+            action = 'CREATE'
+            marker = None
             orchestration_client.stacks.create(**stack_args)
         else:
             self.log.info("Performing Heat stack update")
             # Make sure existing parameters for stack are reused
             stack_args['existing'] = 'true'
+            # Find the last top-level event to use for the first marker
+            events = event_utils.get_events(orchestration_client,
+                                            stack_id=stack_name,
+                                            event_args={'sort_dir': 'desc',
+                                                        'limit': 1})
+            marker = events[0].id if events else None
+            action = 'UPDATE'
+
             orchestration_client.stacks.update(stack.id, **stack_args)
 
+        verbose_events = self.app_args.verbose_level > 0
         create_result = utils.wait_for_stack_ready(
-            orchestration_client, stack_name)
+            orchestration_client, stack_name, marker, action, verbose_events)
         if not create_result:
             if stack is None:
                 raise exceptions.DeploymentError("Heat Stack create failed.")