Add operation ID for remote calls

The operation ID is a random string which can be added in the SOAP
headers of the remote request. vCenter and ESX will append this opID to
every log message associated with the remote request. This allows
administrators to correlate log messages for particular operation across
different systems (OpenStack -> vCenter -> ESX).

There is also addition keyword argument 'skip_op_id' which allows
callers to disable logging the opID if set to True.

Example for correlating logs for CreateVM_Task on devstack, vCenter and
ESX: http://paste.openstack.org/show/592614/

Change-Id: I75cb71c7c58b4ee9cd36fc977eb2a18a911f161f

8 files changed, 91 insertions, 20 deletions

diff --git a/oslo_vmware/api.py b/oslo_vmware/api.py
index a9839c0..ed3a553 100644
--- a/oslo_vmware/api.py
+++ b/oslo_vmware/api.py
@@ -140,7 +140,7 @@ class VMwareAPISession(object):
                  api_retry_count, task_poll_interval, scheme='https',
                  create_session=True, wsdl_loc=None, pbm_wsdl_loc=None,
                  port=443, cacert=None, insecure=True, pool_size=10,
-                 connection_timeout=None):
+                 connection_timeout=None, op_id_prefix='oslo.vmware'):
         """Initializes the API session with given parameters.
 
         :param host: ESX/VC server IP address or host name
@@ -164,6 +164,7 @@ class VMwareAPISession(object):
                           connection pool
         :param connection_timeout: Maximum time in seconds to wait for peer to
                                    respond.
+        :param op_id_prefix: String prefix for the operation ID.
         :raises: VimException, VimFaultException, VimAttributeException,
                  VimSessionOverLoadException
         """
@@ -184,6 +185,7 @@ class VMwareAPISession(object):
         self._insecure = insecure
         self._pool_size = pool_size
         self._connection_timeout = connection_timeout
+        self._op_id_prefix = op_id_prefix
         if create_session:
             self._create_session()
 
@@ -202,7 +204,8 @@ class VMwareAPISession(object):
                                 cacert=self._cacert,
                                 insecure=self._insecure,
                                 pool_maxsize=self._pool_size,
-                                connection_timeout=self._connection_timeout)
+                                connection_timeout=self._connection_timeout,
+                                op_id_prefix=self._op_id_prefix)
         return self._vim
 
     @property
@@ -215,7 +218,8 @@ class VMwareAPISession(object):
                                 cacert=self._cacert,
                                 insecure=self._insecure,
                                 pool_maxsize=self._pool_size,
-                                connection_timeout=self._connection_timeout)
+                                connection_timeout=self._connection_timeout,
+                                op_id_prefix=self._op_id_prefix)
             if self._session_id:
                 # To handle the case where pbm property is accessed after
                 # session creation. If pbm property is accessed before session
@@ -401,13 +405,15 @@ class VMwareAPISession(object):
 
         :param task: managed object reference of the task
         """
-        LOG.debug("Invoking VIM API to read info of task: %s.", task)
         try:
+            # we poll tasks too often, so skip logging the opID as it generates
+            # too much noise in the logs
             task_info = self.invoke_api(vim_util,
                                         'get_object_property',
                                         self.vim,
                                         task,
-                                        'info')
+                                        'info',
+                                        skip_op_id=True)
         except exceptions.VimException:
             with excutils.save_and_reraise_exception():
                 LOG.exception(_LE("Error occurred while reading info of "
diff --git a/oslo_vmware/pbm.py b/oslo_vmware/pbm.py
index b0c60af..df5b33f 100644
--- a/oslo_vmware/pbm.py
+++ b/oslo_vmware/pbm.py
@@ -42,7 +42,7 @@ class Pbm(service.Service):
 
     def __init__(self, protocol='https', host='localhost', port=443,
                  wsdl_url=None, cacert=None, insecure=True, pool_maxsize=10,
-                 connection_timeout=None):
+                 connection_timeout=None, op_id_prefix='oslo.vmware'):
         """Constructs a PBM service client object.
 
         :param protocol: http or https
@@ -55,13 +55,15 @@ class Pbm(service.Service):
                          used only if cacert is not specified
         :param pool_maxsize: Maximum number of connections in http
                              connection pool
+        :param op_id_prefix: String prefix for the operation ID.
         :param connection_timeout: Maximum time in seconds to wait for peer to
                                    respond.
         """
         base_url = service.Service.build_base_url(protocol, host, port)
         soap_url = base_url + '/pbm'
         super(Pbm, self).__init__(wsdl_url, soap_url, cacert, insecure,
-                                  pool_maxsize, connection_timeout)
+                                  pool_maxsize, connection_timeout,
+                                  op_id_prefix)
 
     def set_soap_cookie(self, cookie):
         """Set the specified vCenter session cookie in the SOAP header
diff --git a/oslo_vmware/service.py b/oslo_vmware/service.py
index 477a6c3..0a67cad 100644
--- a/oslo_vmware/service.py
+++ b/oslo_vmware/service.py
@@ -22,6 +22,7 @@ import os
 
 import netaddr
 from oslo_utils import timeutils
+from oslo_utils import uuidutils
 import requests
 import six
 import six.moves.http_client as httplib
@@ -29,6 +30,7 @@ import suds
 from suds import cache
 from suds import client
 from suds import plugin
+import suds.sax.element as element
 from suds import transport
 
 from oslo_vmware._i18n import _
@@ -70,6 +72,7 @@ class ServiceMessagePlugin(plugin.MessagePlugin):
         # Suds builds the entire request object based on the WSDL schema.
         # VI SDK throws server errors if optional SOAP nodes are sent
         # without values; e.g., <test/> as opposed to <test>test</test>.
+
         context.envelope.prune()
         context.envelope.walk(self.add_attribute_for_value)
 
@@ -194,9 +197,10 @@ class Service(object):
 
     def __init__(self, wsdl_url=None, soap_url=None,
                  cacert=None, insecure=True, pool_maxsize=10,
-                 connection_timeout=None):
+                 connection_timeout=None, op_id_prefix='oslo.vmware'):
         self.wsdl_url = wsdl_url
         self.soap_url = soap_url
+        self.op_id_prefix = op_id_prefix
         LOG.debug("Creating suds client with soap_url='%s' and wsdl_url='%s'",
                   self.soap_url, self.wsdl_url)
         transport = RequestsTransport(cacert=cacert,
@@ -260,6 +264,17 @@ class Service(object):
                                                fault_string,
                                                details=details)
 
+    def _add_operation_id(self, op_id):
+        """Add operation ID for the next remote call to vCenter.
+
+        The operation ID is a random string which allows to correlate log
+        messages across different systems (OpenStack, vCenter, ESX).
+        """
+        headers = [element.Element('operationID').setText(op_id)]
+        if self.client.options.soapheaders is not None:
+            headers.append(self.client.options.soapheaders)
+        self.client.set_options(soapheaders=headers)
+
     @property
     def service_content(self):
         if self._service_content is None:
@@ -297,6 +312,18 @@ class Service(object):
                                                         managed_object)
                 if managed_object is None:
                     return
+
+                skip_op_id = kwargs.pop('skip_op_id', False)
+                if not skip_op_id:
+                    # Generate opID. It will appear in vCenter and ESX logs for
+                    # this particular remote call.
+                    op_id = '%s-%s' % (self.op_id_prefix,
+                                       uuidutils.generate_uuid())
+                    LOG.debug('Invoking %s.%s with opID=%s',
+                              managed_object._type,
+                              attr_name,
+                              op_id)
+                    self._add_operation_id(op_id)
                 request = getattr(self.client.service, attr_name)
                 response = request(managed_object, **kwargs)
                 if (attr_name.lower() == 'retrievepropertiesex'):
diff --git a/oslo_vmware/tests/test_api.py b/oslo_vmware/tests/test_api.py
index fbc4c8d..9a002bd 100644
--- a/oslo_vmware/tests/test_api.py
+++ b/oslo_vmware/tests/test_api.py
@@ -137,7 +137,8 @@ class VMwareAPISessionTest(base.TestCase):
             cacert=self.cert_mock,
             insecure=False,
             pool_maxsize=VMwareAPISessionTest.POOL_SIZE,
-            connection_timeout=None)
+            connection_timeout=None,
+            op_id_prefix='oslo.vmware')
 
     @mock.patch.object(pbm, 'Pbm')
     def test_pbm(self, pbm_mock):
@@ -412,7 +413,8 @@ class VMwareAPISessionTest(base.TestCase):
         api_session.invoke_api.assert_called_with(vim_util,
                                                   'get_object_property',
                                                   api_session.vim, task,
-                                                  'info')
+                                                  'info',
+                                                  skip_op_id=True)
         self.assertEqual(task_info_list_size,
                          api_session.invoke_api.call_count)
 
@@ -437,7 +439,8 @@ class VMwareAPISessionTest(base.TestCase):
         api_session.invoke_api.assert_called_with(vim_util,
                                                   'get_object_property',
                                                   api_session.vim, task,
-                                                  'info')
+                                                  'info',
+                                                  skip_op_id=True)
         self.assertEqual(task_info_list_size,
                          api_session.invoke_api.call_count)
 
@@ -453,7 +456,8 @@ class VMwareAPISessionTest(base.TestCase):
         api_session.invoke_api.assert_called_once_with(vim_util,
                                                        'get_object_property',
                                                        api_session.vim, task,
-                                                       'info')
+                                                       'info',
+                                                       skip_op_id=True)
 
     def test_wait_for_lease_ready(self):
         api_session = self._create_api_session(True)
diff --git a/oslo_vmware/tests/test_service.py b/oslo_vmware/tests/test_service.py
index d11b38c..1accb92 100644
--- a/oslo_vmware/tests/test_service.py
+++ b/oslo_vmware/tests/test_service.py
@@ -374,6 +374,31 @@ class ServiceTest(base.TestCase):
         svc_obj.client.options.transport.cookiejar = [cookie]
         self.assertIsNone(svc_obj.get_http_cookie())
 
+    def test_add_operation_id(self):
+        def fake_set_options(*args, **kwargs):
+            headers = kwargs['soapheaders']
+            self.assertEqual(1, len(headers))
+            txt = headers[0].getText()
+            self.assertEqual('fira-12345', txt)
+
+        svc_obj = service.Service()
+        svc_obj.client.options.soapheaders = None
+        setattr(svc_obj.client, 'set_options', fake_set_options)
+        svc_obj._add_operation_id('fira-12345')
+
+    def test_add_operation_id_with_existing_header(self):
+        def fake_set_options(*args, **kwargs):
+            headers = kwargs['soapheaders']
+            self.assertEqual(2, len(headers))
+            txt = headers[0].getText()
+            self.assertEqual('fira-12345', txt)
+            self.assertEqual('vc-session-cookie', headers[1])
+
+        svc_obj = service.Service()
+        svc_obj.client.options.soapheaders = 'vc-session-cookie'
+        setattr(svc_obj.client, 'set_options', fake_set_options)
+        svc_obj._add_operation_id('fira-12345')
+
 
 class MemoryCacheTest(base.TestCase):
     """Test class for MemoryCache."""
diff --git a/oslo_vmware/tests/test_vim_util.py b/oslo_vmware/tests/test_vim_util.py
index a542509..8e43c95 100644
--- a/oslo_vmware/tests/test_vim_util.py
+++ b/oslo_vmware/tests/test_vim_util.py
@@ -222,7 +222,8 @@ class VimUtilTest(base.TestCase):
         moref._type = "VirtualMachine"
         retrieve_result = mock.Mock()
 
-        def vim_RetrievePropertiesEx_side_effect(pc, specSet, options):
+        def vim_RetrievePropertiesEx_side_effect(pc, specSet, options,
+                                                 skip_op_id=False):
             self.assertTrue(pc is vim.service_content.propertyCollector)
             self.assertEqual(1, options.maxObjects)
 
@@ -361,7 +362,7 @@ class VimUtilTest(base.TestCase):
         val = vim_util.get_object_property(vim, moref, property_name)
         self.assertEqual(prop.val, val)
         get_object_properties.assert_called_once_with(
-            vim, moref, [property_name])
+            vim, moref, [property_name], skip_op_id=False)
 
     def test_find_extension(self):
         vim = mock.Mock()
diff --git a/oslo_vmware/vim.py b/oslo_vmware/vim.py
index e849246..a97ffc2 100644
--- a/oslo_vmware/vim.py
+++ b/oslo_vmware/vim.py
@@ -21,7 +21,7 @@ class Vim(service.Service):
 
     def __init__(self, protocol='https', host='localhost', port=None,
                  wsdl_url=None, cacert=None, insecure=True, pool_maxsize=10,
-                 connection_timeout=None):
+                 connection_timeout=None, op_id_prefix='oslo.vmware'):
         """Constructs a VIM service client object.
 
         :param protocol: http or https
@@ -36,6 +36,7 @@ class Vim(service.Service):
                              connection pool
         :param connection_timeout: Maximum time in seconds to wait for peer to
                                    respond.
+        :param op_id_prefix: String prefix for the operation ID.
         :raises: VimException, VimFaultException, VimAttributeException,
                  VimSessionOverLoadException, VimConnectionException
         """
@@ -44,7 +45,8 @@ class Vim(service.Service):
         if wsdl_url is None:
             wsdl_url = soap_url + '/vimService.wsdl'
         super(Vim, self).__init__(wsdl_url, soap_url, cacert, insecure,
-                                  pool_maxsize, connection_timeout)
+                                  pool_maxsize, connection_timeout,
+                                  op_id_prefix)
 
     def retrieve_service_content(self):
         return self.RetrieveServiceContent(service.SERVICE_INSTANCE)
diff --git a/oslo_vmware/vim_util.py b/oslo_vmware/vim_util.py
index 511daf6..24d9286 100644
--- a/oslo_vmware/vim_util.py
+++ b/oslo_vmware/vim_util.py
@@ -285,13 +285,14 @@ def get_objects(vim, type_, max_objects, properties_to_collect=None,
                                     options=options)
 
 
-def get_object_properties(vim, moref, properties_to_collect):
+def get_object_properties(vim, moref, properties_to_collect, skip_op_id=False):
     """Get properties of the given managed object.
 
     :param vim: Vim object
     :param moref: managed object reference
     :param properties_to_collect: names of the managed object properties to be
                                   collected
+    :param skip_op_id: whether to skip putting opID in the request
     :returns: properties of the given managed object
     :raises: VimException, VimFaultException, VimAttributeException,
              VimSessionOverLoadException, VimConnectionException
@@ -317,7 +318,8 @@ def get_object_properties(vim, moref, properties_to_collect):
     retrieve_result = vim.RetrievePropertiesEx(
         vim.service_content.propertyCollector,
         specSet=[property_filter_spec],
-        options=options)
+        options=options,
+        skip_op_id=skip_op_id)
     cancel_retrieval(vim, retrieve_result)
     return retrieve_result.objects
 
@@ -422,17 +424,19 @@ class WithRetrieval(object):
                 self.vim, self.retrieve_result)
 
 
-def get_object_property(vim, moref, property_name):
+def get_object_property(vim, moref, property_name, skip_op_id=False):
     """Get property of the given managed object.
 
     :param vim: Vim object
     :param moref: managed object reference
     :param property_name: name of the property to be retrieved
+    :param skip_op_id: whether to skip putting opID in the request
     :returns: property of the given managed object
     :raises: VimException, VimFaultException, VimAttributeException,
              VimSessionOverLoadException, VimConnectionException
     """
-    props = get_object_properties(vim, moref, [property_name])
+    props = get_object_properties(vim, moref, [property_name],
+                                  skip_op_id=skip_op_id)
     prop_val = None
     if props:
         prop = None