Merge "Add operation ID for remote calls"

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