Log stack status changes in unit tests

We no longer always persist status changes to the database in
Stack.state_set() - in most cases we wait until the stack lock is released
when existing the thread, so as to be able to make the change cheaply and
atomically. However, in the unit tests we don't generally have a lock and
operations are not generally run in a thread anyway. Since the logging is
close to the database storage call, this means that there is no logging
when a stack fails in a unit test. This makes debugging failing tests a
giant pain, as you can never see what happened.

This moves the INFO log back to the state_set() method itself. To replace
the INFO log, there's also a DEBUG log so we can continue to see when the
state actually gets persisted.

Change-Id: I781c403ac07b1c9b25ac815600b37be161103ce7

heat/engine/stack.py

@@ -918,6 +918,7 @@ class Stack(collections.Mapping):
         self.action = action
         self.status = status
         self.status_reason = reason
+        self._log_status()
 
         if self.convergence and action in (
                 self.UPDATE, self.DELETE, self.CREATE,
@@ -942,6 +943,14 @@ class Stack(collections.Mapping):
                 self.UPDATE, self.DELETE, self.ROLLBACK):
             self._persist_state()
 
+    def _log_status(self):
+        LOG.info(_LI('Stack %(action)s %(status)s (%(name)s): '
+                     '%(reason)s'),
+                 {'action': self.action,
+                  'status': self.status,
+                  'name': self.name,
+                  'reason': self.status_reason})
+
     def _persist_state(self):
         """Persist stack state to database"""
         if self.id is None:
@@ -965,14 +974,12 @@ class Stack(collections.Mapping):
                 stack.update_and_save(values)
 
     def _send_notification_and_add_event(self):
+        LOG.debug('Persisting stack %(name)s status %(action)s %(status)s',
+                  {'action': self.action,
+                   'status': self.status,
+                   'name': self.name})
         notification.send(self)
         self._add_event(self.action, self.status, self.status_reason)
-        LOG.info(_LI('Stack %(action)s %(status)s (%(name)s): '
-                     '%(reason)s'),
-                 {'action': self.action,
-                  'status': self.status,
-                  'name': self.name,
-                  'reason': self.status_reason})
 
     def persist_state_and_release_lock(self, engine_id):
         """Persist stack state to database and release stack lock"""
@@ -1549,6 +1556,7 @@ class Stack(collections.Mapping):
             # condition with the COMPLETE status
             self.action = action
 
+            self._log_status()
             self._send_notification_and_add_event()
             if self.status == self.FAILED:
                 # Since template was incrementally updated based on existing