Improve logging for task updates

This patch would print the task name while waiting
for tasks to complete and also update total duration
in seconds on successful completion.

Change-Id: Ia1448cc9baf1cf7abc7d4b14e27e90c86af5583c

2 files changed, 20 insertions, 3 deletions

diff --git a/oslo_vmware/api.py b/oslo_vmware/api.py
index aaeb77b..323462b 100644
--- a/oslo_vmware/api.py
+++ b/oslo_vmware/api.py
@@ -408,13 +408,25 @@ class VMwareAPISession(object):
                                   "task: %s."),
                               task)
         else:
+            task_detail = {'id': task.value}
+            # some internal tasks do not have 'name' set
+            if getattr(task_info, 'name', None):
+                task_detail['name'] = task_info.name
+
             if task_info.state in ['queued', 'running']:
                 if hasattr(task_info, 'progress'):
                     LOG.debug("Task: %(task)s progress is %(progress)s%%.",
-                              {'task': task,
+                              {'task': task_detail,
                                'progress': task_info.progress})
             elif task_info.state == 'success':
-                LOG.debug("Task: %s status is success.", task)
+                def get_completed_task():
+                    complete_time = getattr(task_info, 'completeTime', None)
+                    if complete_time:
+                        duration = complete_time - task_info.queueTime
+                        task_detail['duration_secs'] = duration.total_seconds()
+                    return task_detail
+                LOG.debug("Task: %s completed successfully.",
+                          get_completed_task())
                 raise loopingcall.LoopingCallDone(task_info)
             else:
                 error_msg = six.text_type(task_info.error.localizedMessage)
diff --git a/oslo_vmware/tests/test_api.py b/oslo_vmware/tests/test_api.py
index c402d47..f108167 100644
--- a/oslo_vmware/tests/test_api.py
+++ b/oslo_vmware/tests/test_api.py
@@ -18,6 +18,7 @@
 Unit tests for session management and API invocation classes.
 """
 
+from datetime import datetime
 from eventlet import greenthread
 import mock
 import six
@@ -399,6 +400,8 @@ class VMwareAPISessionTest(base.TestCase):
             (state, progress) = task_info_list.pop(0)
             task_info = mock.Mock()
             task_info.progress = progress
+            task_info.queueTime = datetime(2016, 12, 6, 15, 29, 43, 79060)
+            task_info.completeTime = datetime(2016, 12, 6, 15, 29, 50, 79060)
             task_info.state = state
             return task_info
 
@@ -538,9 +541,11 @@ class VMwareAPISessionTest(base.TestCase):
         with (
             mock.patch.object(api_session, 'invoke_api', fake_invoke_api)
         ):
+            fake_task = mock.Mock()
+            fake_task.value = 'task-1'
             self.assertRaises(expected_exception,
                               api_session._poll_task,
-                              'fake-task')
+                              fake_task)
 
     def test_poll_task_well_known_exceptions(self):
         for k, v in six.iteritems(exceptions._fault_classes_registry):