From 6a63362919c12023798458e721a4818e61702e3a Mon Sep 17 00:00:00 2001 From: Radoslav Gerganov Date: Fri, 16 Dec 2016 13:47:32 +0200 Subject: [PATCH] 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 --- oslo_vmware/api.py | 16 +++++++++++----- oslo_vmware/pbm.py | 6 ++++-- oslo_vmware/service.py | 29 ++++++++++++++++++++++++++++- oslo_vmware/tests/test_api.py | 12 ++++++++---- oslo_vmware/tests/test_service.py | 25 +++++++++++++++++++++++++ oslo_vmware/tests/test_vim_util.py | 5 +++-- oslo_vmware/vim.py | 6 ++++-- oslo_vmware/vim_util.py | 12 ++++++++---- 8 files changed, 91 insertions(+), 20 deletions(-) diff --git a/oslo_vmware/api.py b/oslo_vmware/api.py index a9839c07..ed3a5535 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 b0c60af5..df5b33f8 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 477a6c3f..0a67cad2 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., as opposed to 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 fbc4c8de..9a002bd2 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 d11b38cc..1accb92f 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 a542509b..8e43c955 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 e8492463..a97ffc2c 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 511daf68..24d92861 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