Fix confusing logging when running asynchronous commands

We log them as completed when they start executing.

Also fix a problem in remove_large_keys that prevented items
with defaultdict from being logged.

Change-Id: I34a06cc85f55c693416f8c4c9877d55d6affafc9

2 files changed, 14 insertions, 12 deletions

diff --git a/ironic_python_agent/extensions/base.py b/ironic_python_agent/extensions/base.py
index d2ea4337..98554511 100644
--- a/ironic_python_agent/extensions/base.py
+++ b/ironic_python_agent/extensions/base.py
@@ -164,7 +164,7 @@ class AsyncCommandResult(BaseCommandResult):
 
             if isinstance(result, (bytes, str)):
                 result = {'result': '{}: {}'.format(self.command_name, result)}
-            LOG.info('Command: %(name)s, result: %(result)s',
+            LOG.info('Asynchronous command %(name)s completed: %(result)s',
                      {'name': self.command_name,
                       'result': utils.remove_large_keys(result)})
             with self.command_state_lock:
@@ -270,9 +270,6 @@ class ExecuteCommandMixin(object):
                 # recorded as a failed SyncCommandResult with an error message
                 LOG.exception('Command execution error: %s', e)
                 result = SyncCommandResult(command_name, kwargs, False, e)
-            LOG.info('Command %(name)s completed: %(result)s',
-                     {'name': command_name,
-                      'result': utils.remove_large_keys(result)})
             self.command_results[result.id] = result
             return result
 
@@ -299,10 +296,13 @@ def async_command(command_name, validator=None):
             # know about the mode
             bound_func = functools.partial(func, self)
 
-            return AsyncCommandResult(command_name,
-                                      command_params,
-                                      bound_func,
-                                      agent=self.agent).start()
+            ret = AsyncCommandResult(command_name,
+                                     command_params,
+                                     bound_func,
+                                     agent=self.agent).start()
+            LOG.info('Asynchronous command %(name)s started execution',
+                     {'name': command_name})
+            return ret
         return wrapper
     return async_decorator
 
@@ -325,6 +325,9 @@ def sync_command(command_name, validator=None):
                 validator(self, **command_params)
 
             result = func(self, **command_params)
+            LOG.info('Synchronous command %(name)s completed: %(result)s',
+                     {'name': command_name,
+                      'result': utils.remove_large_keys(result)})
             return SyncCommandResult(command_name,
                                      command_params,
                                      True,
diff --git a/ironic_python_agent/utils.py b/ironic_python_agent/utils.py
index 211070ac..637737dd 100644
--- a/ironic_python_agent/utils.py
+++ b/ironic_python_agent/utils.py
@@ -634,10 +634,9 @@ _LARGE_KEYS = frozenset(['configdrive', 'system_logs'])
 def remove_large_keys(var):
     """Remove specific keys from the var, recursing into dicts and lists."""
     if isinstance(var, abc.Mapping):
-        return var.__class__(
-            (key, remove_large_keys(value)
-             if key not in _LARGE_KEYS else '<...>')
-            for key, value in var.items())
+        return {key: (remove_large_keys(value)
+                      if key not in _LARGE_KEYS else '<...>')
+                for key, value in var.items()}
     elif isinstance(var, abc.Sequence) and not isinstance(var, str):
         return var.__class__(map(remove_large_keys, var))
     else: