Clean up logging related to new state machine

* Do not log every function call. It was nice for debugging, but now it just
  clutters the logs. Expecially when we log arguments, containing
  the whole inventory.
* Do not log "state None", it's not helpful.
* Move state assignment down in NodeCache.__init__, otherwise it's always
  overwritten by invalidate_cache() call.

Change-Id: Ic7e8f6a6c3957684be2f6f80529aa7776df81153

ironic_inspector/node_cache.py

@@ -71,12 +71,12 @@ class NodeInfo(object):
                  finished_at=None, error=None, node=None, ports=None,
                  ironic=None, lock=None):
         self.uuid = uuid
-        self._version_id = version_id
-        self._state = state
         self.started_at = started_at
         self.finished_at = finished_at
         self.error = error
         self.invalidate_cache()
+        self._version_id = version_id
+        self._state = state
         self._node = node
         if ports is not None and not isinstance(ports, dict):
             ports = {p.address: p for p in ports}
@@ -97,8 +97,10 @@ class NodeInfo(object):
 
     def __str__(self):
         """Self represented as an UUID and a state."""
-        return _("%(uuid)s state %(state)s") % {'uuid': self.uuid,
-                                                'state': self._state}
+        parts = [self.uuid]
+        if self._state:
+            parts += [_('state'), self._state]
+        return ' '.join(parts)
 
     def acquire_lock(self, blocking=True):
         """Acquire a lock on the associated node.
@@ -555,10 +557,6 @@ def fsm_event_before(event, strict=False):
                       '%(func)s', {'event': event, 'func': func},
                       node_info=node_info)
             node_info.fsm_event(event, strict=strict)
-            LOG.debug('Calling: %(func)s(<node>, *%(args_)s, '
-                      '**%(kwargs_)s)', {'func': func, 'args_': args,
-                                         'kwargs_': kwargs},
-                      node_info=node_info)
             return func(node_info, *args, **kwargs)
         return inner
     return outer
@@ -576,10 +574,6 @@ def fsm_event_after(event, strict=False):
     def outer(func):
         @six.wraps(func)
         def inner(node_info, *args, **kwargs):
-            LOG.debug('Calling: %(func)s(<node>, *%(args_)s, '
-                      '**%(kwargs_)s)', {'func': func, 'args_': args,
-                                         'kwargs_': kwargs},
-                      node_info=node_info)
             ret = func(node_info, *args, **kwargs)
             LOG.debug('Processing event %(event)s after calling '
                       '%(func)s', {'event': event, 'func': func},

ironic_inspector/test/unit/test_utils.py

@@ -141,7 +141,12 @@ class TestProcessingLogger(base.BaseTest):
 
     def test_prefix_NodeInfo_instance(self):
         node_info = node_cache.NodeInfo('NNN')
-        self.assertEqual('[node: NNN state None]',
+        self.assertEqual('[node: NNN]',
+                         utils.processing_logger_prefix(node_info=node_info))
+
+    def test_prefix_NodeInfo_instance_with_state(self):
+        node_info = node_cache.NodeInfo('NNN', state='foobar')
+        self.assertEqual('[node: NNN state foobar]',
                          utils.processing_logger_prefix(node_info=node_info))
 
     def test_adapter_no_bmc(self):