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
(cherry picked from commit 0eee26ea66)
(cherry picked from commit c9876dd937)

ironic_python_agent/extensions/base.py

@@ -163,7 +163,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:
@@ -269,9 +269,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
 
@@ -298,10 +295,13 @@ def async_command(command_name, validator=None):
             # know about the mode
             bound_func = functools.partial(func, self)
 
-            return AsyncCommandResult(command_name,
+            ret = AsyncCommandResult(command_name,
-                                      command_params,
+                                     command_params,
-                                      bound_func,
+                                     bound_func,
-                                      agent=self.agent).start()
+                                     agent=self.agent).start()
+            LOG.info('Asynchronous command %(name)s started execution',
+                     {'name': command_name})
+            return ret
         return wrapper
     return async_decorator
 
@@ -324,6 +324,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,

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__(
+        return {key: (remove_large_keys(value)
-            (key, remove_large_keys(value)
+                      if key not in _LARGE_KEYS else '<...>')
-             if key not in _LARGE_KEYS else '<...>')
+                for key, value in var.items()}
-            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: