diff --git a/docs/appendix.rst b/docs/appendix.rst index 6d66ff6d0..0fd5e9dc8 100644 --- a/docs/appendix.rst +++ b/docs/appendix.rst @@ -29,6 +29,14 @@ This documentation uses a few special terms to refer to Python types: :class:`py3:bytes` in Python 3). Unless otherwise indicated, byte strings in pywbem are always UTF-8 encoded. + connection id + a string (:term:`string`) that uniquely identifies each + :class:`pywbem.WBEMConnection` object created. The connection id is + immutable and is accessible from + :attr:`pywbem.WBEMConnection.conn_id`. It is included in of each log + record created for pywbem log output and may be used to correlate pywbem + log records for a single connection. + number one of the number types :class:`py:int`, :class:`py2:long` (Python 2 only), or :class:`py:float`. diff --git a/docs/client/logging.rst b/docs/client/logging.rst index 4ad2e147f..d15dfcfad 100644 --- a/docs/client/logging.rst +++ b/docs/client/logging.rst @@ -7,10 +7,3 @@ WBEM operation logging .. automodule:: pywbem._logging :members: -.. # Note: Using the :members: option on automodule includes its data -.. # members automatically, but also recursively includes its class -.. # PywbemLoggers, showing it with the submodule namespace: -.. # pywbem._logging.PywbemLoggers. It seems the only way to not show the -.. # submodule namespace would be to have an autodata directive for each of -.. # the 6 (or so) public data items in the module, and a separate autoclass -.. # directive. diff --git a/pywbem/_logging.py b/pywbem/_logging.py index 6441d11a1..cd408b4ea 100644 --- a/pywbem/_logging.py +++ b/pywbem/_logging.py @@ -16,9 +16,13 @@ # pylint: disable=line-too-long """ -**Experimental:** *New in pywbem 0.11 as experimental.* +**Experimental:** *Configuration methods completely rewritten in pywbem 0.12.* -The pywbem package implements selected logging based on the Python +.. _`Pywbem logging overview`: + +Pywbem logging overview +^^^^^^^^^^^^^^^^^^^^^^^ +The pywbem package implements selected logging using on the Python :mod:`py:logging` facility. Pywbem logging is used to record information passing between the pywbem client @@ -27,147 +31,170 @@ the pywbem API user as Python exceptions rather than being recorded in a log by a pywbem logger. -Pywbem logging defines two :class:`~py:logging.Logger` objects +Pywbem logging defines two Python :class:`~py:logging.Logger` objects (named loggers): -* ``pywbem.api`` - logs user-issued calls to :class:`~pywbem.WBEMConnection` - methods that drive WBEM operations (see :ref:`WBEM operations`) and the +* ``pywbem.api`` - Logs user-issued calls to :class:`~pywbem.WBEMConnection` + methods that drive WBEM operations (see :ref:`WBEM operations`) and their responses before they are passed back to the user. Log entries are defined at DEBUG log level. This logs the parameters of each request and the results - including CIMObjects/exceptions in each method repoonse. + including CIMObjects/exceptions in each method response. It also logs the + creation of the :class:`~pywbem.WBEMConnection` object to capture connection + information. -* ``pywbem.http`` - logs HTTP requests and responses between the pywbem client +* ``pywbem.http`` - Logs HTTP requests and responses between the pywbem client and WBEM server. This logs the http request data and response data including http headers and XML payload. -The above logger names create log entries when is configured, logging is at -the DEBUG log level and logging is activated for one or more WBEMConnections. - -There are three parts to configuration of the pywbem loggers: - -* **Configure the loggers** - This sets the Python logging parameters that - control the logger and its output (handler, etc.) and may be - done by either Python logging methods or methods within - :class:`~pywbem.WBEMConnection`. - -* **Set the `detail_level` for pywbem logging** - Because pywbem logs can - generate large quantities of information, pywbem allows the user to control - the quantity of information in each log. This is a pywbem feature so it - can only be configured by the pywbem :class:`~pywbem.WBEMConnection` - methods and :func:define_loggers_from_string` that configure pywbem loggers. - The detail levels options are defined in :data:`LOG_DETAIL_LEVELS` - -* **Activate the pywbem loggers** - A pywbem logger is activated when it is - connected to one or more WBEMConnections so that log records will be generated - when any of the WBEMConnection methods that communicates with a WBEM server - is executed for that WBEMConnection. Pywbem separates the configuration - of the loggers from activation to allow logger configuration by either pywbem - methods or standard Python logging methods. Activation is controlled by - the `connection` parameter of :meth:`~pywbem.WBEMConnection.configure_logger` - or :func:`define_loggers_from_string`. - -These loggers are only active for a :class:`~pywbem.WBEMConnection` object when: - -* A logger in the Python logger name hiearchy higher than or equal to the - pywbem loggers (ex `pywbem` or root) is defined before the the logger is - attached to :class:`~pywbem.WBEMConnection` object with one of the - :class:`~pywbem.WBEMConnection` methods. - Configuring the loggers through standard Python logger handler methods - does not activate these loggers since the logger is not linked to a - :class:`~pywbem.WBEMConnection` object. - -* The logger is activated by linking it to a :class:`~pywbem.WBEMConnection` - object using the `connection` parameter of the configure... method. - -* The pywbem loggers may be configured through any of the following - pywbem methods. These methods configure and optionally activate each of the - loggers: - - * :meth:`~pywbem.WBEMConnection.configure_logger` which configures and - optionally activates one or more of the loggers that log user-issued calls - to :class:~pywbem.WBEMConnection methods that drive WBEM operations and - pywbem http requests and responses. - - * :func:`define_loggers_from_string` which allows configuring and activating - the pywbem loggers from a single formatted string. This is most useful - in defining the loggers from a command line tool such as pywbemcli. Thus, - for example, the following string could be used to configure and activate - both loggers:: +The above logger names output log records when they are configured and +activated. The pywbem loggers log at the DEBUG log level and when +logging is activated for one or more :class:`~pywbem.WBEMConnection` instance +objects. + +There are three components to configuration of the pywbem loggers: + +* **Configure Python logger names** - Sets the Python logger parameters + (logging handlers, message formats, etc.). Either Python logging + methods or methods defined in :ref:`Logging configuration methods` may be + used to configure the loggers. The `dest` parameter of the pywbem methods + configures the loggers for either stream or file loggers and the `name` + parameter defines which of the pywbem loggers is being configured. This + configure step does not activate any pywbem logger. If no loggers are + configured, pywbem defaults to a logger with the Python + logging NullHandler. + +* **Set the log record detail level for pywbem loggers(Optional)** - Because + pywbem logs can generate large quantities of information, they allow the user + to control the quantity of information in each log record. This is a pywbem + feature so it can only be configured using the pywbem methods defined in + :ref:`Logging configuration methods` using the `detail_level` parameter. The + `detail_level` possible values are defined in + :data:`~pywbem_logging.LOG_DETAIL_LEVELS`. The default for `detail_level` is + `all` which logs all if the data in the requests and responses if the + `detail_level` parameter is not set. + +* **Activate the pywbem loggers** - A pywbem logger is activated to + actually output log records when any of the WBEMConnection methods that + communicate with a WBEM server are executed for that WBEMConnection object. + Activation is controlled by the `connection` parameter of the + methods defined in :ref:`Logging configuration methods` which + activates logging for all subsequently created + :class:`~pywbem.WBEMConnection` objects or for a particular WBEMConnection + object. + +.. _`Logging configuration methods`: + +Logging configuration methods +^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ +The pywbem loggers may be configured through the following pywbem methods. These +methods must be used to set the log detail_level and activate the loggers. + + * :meth:`~pywbem.WBEMConnection.configure_logger` - Configures and + optionally activates one or loggers. If the logger name is 'all' + it acts on both loggers. For example:: + + conn = WBEMConnection(...) + WBEMConnection.configure_logger('api', dest=file, log_filename='blah.log' + connection=conn) + + * :func:`configure_loggers_from_string` - Allows configuring and + activating the pywbem loggers from a single formatted string. This is most + useful in defining the loggers from a command line tool such as pywbemcli. + Thus, for example, the following could be used to configure and + activate both loggers:: + + configure_loggers_from_string('api=file:summary,http=stderr:all', + log_filename='mylog.log', + connection='True') + +.. _`Logging configuration Examples`: + +Logging configuration examples +^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ + +Configure and activate loggers with +:meth:`~pywbem.WBEMConnection.configure_logger`. + +* Configure the "pywbem.api" logger for summary information output to a file + and activate that logger for all subsequently created + :class:`~pywbem.WBEMConnection` objects:: + + WBEMConnection.configure_logger('api', dest='stderr', + detail_level='summary', + connection=True) + conn = WBEMConnection() # logs WBEMConnection api calls and responses + +* Configure and activate a single :class:`~pywbem.WBEMConnection` object logger + for output of summary information for both "pywbem.api" and "pywbem.http":: - api=file:summary,http=stderr:all + conn = WBEMConnection() + WBEMConnection.configure_logger('all', dest='file', log_filname='xxx.log', + connection=conn) -The following examples define several different logger configuration options: +Configure pywbem logging using Python logging methods. -Configure a single pywbem connection with standard Python logger methods by -defining the root logger with basicConfig:: +* Configure a single pywbem connection with standard Python logger methods by + defining the root logger with basicConfig:: # Set basic logging configuration (i.e root level logger) import logging logging.basicConfig(filename='example.log',level=logging.DEBUG) conn = WBEMConnection(...) - # Define the detail_level and WBEMConnection object ot activate. - WBEMConnection.configure_all_loggers(detail_level='all', connection=conn) + # Define the detail_level and WBEMConnection object to activate. + WBEMConnection.configure_logger('all', detail_level='all', connection=conn) + -Set up configuration to enable the api logger for all subsequent WBEMConnections -using Python methods to configure the loggers so all `pywbem` loggers are -configured:: +* Configure the `pywbem` logger with a RotatingFileHandler for all + subsequent WBEMConnections using Python methods to configure the logger. + This defines the configuration for both `pywbem.api` and `pywbem.http` + loggers:: - # Define logger for pywbem + from logging.handlers import RotatingFileHandler + # define logger handler for `pywbem`, parent for pywbem.http and pywbem.api logger = logging.getLogger('pywbem') - handler = logging.StreamHandler() + handler = logging.handlers.RotatingFileHandler("my_log.log", maxBytes=2000, + backupCount=10) handler.setLevel(logging.DEBUG) formatter = logging.Formatter('%(asctime)s - %(name)s - %(message)s') handler.setFormatter(formatter) logger.addHandler(handler) - # configure detail_level and set connection so all WBEMConnection objects + # configure detail_level and connection so all WBEMConnection objects # are activated. - WBEMConnection.configure_api_logger(detail_level='summary', connection=True) + WBEMConnection.configure_logger('api', detail_level='summary', + connection=True) # All of the following connections do api call and response logging with # summary information. - WBEMConnection.WBEMConnection(...) - WBEMConnection.WBEMConnection(...) - - -Configure the api logger for summary information output using only pywbem -methods to configure the logger:: + conn1 = WBEMConnection.WBEMConnection(...) + conn2 = WBEMConnection.WBEMConnection(...) - WBEMConnection.configure_api_logger(dest='stderr', - detail_level='summary', - connection=True) +Configure and activate loggers using :func:`configure_loggers_from_string`. - conn = WBEMConnection() - -Configure just a single WBEMConnection for output of summary information:: +* Log everything to stderr and output all of the information using the + pywbem method that configures the loggers from a string:: + configure_loggers_from_string('all=stderr:summary', connection=True) conn = WBEMConnection() - WBEMConnection.configure_api_logger(dest='file', log_filname='xxx.log', - connection=conn) -Log everything to stderr and output all of the information using the -pywbem method that configures the loggers from a string:: - - define_loggers_from_string('all=stderr':summary', connection=True) - conn = WBEMConnection() +* Log api calls and responses summary information to stderr:: -or:: - - define_loggers_from_string('api=stderr':summary,http=summary', + configure_loggers_from_string('api=stderr:summary,http=summary', connection=True) - conn = WBEMConnection() + conn = WBEMConnection(...) -Log only http requests and responses including all infomration in the -requests and responses to a file:: +The keywords in the log record: ()'Connection', 'Request', 'Return' or +'Exception') identify whether the log record is connection data, +api/http request data, api/http response data, or an api exception data. - define_logger('http', 'file', log_filename='mylog.log') - conn = WBEMConnection(..., enable_log='all') +The logger names that create log entries are uniquely identified by appending +(:attr:`~pywbem.WBEMConnection.conn_id`) to the configured logger names so that +different logger names exist for each :class:~pywbem.WBEMConnection object. +Thus the logger record names are of the form `pywbem..conn_id`. -The logger names themselves are uniquely identified with an id string for -each WBEMconnection (:attr:`~pywbem.WBEMConnection.conn_id`). For example, the -log records may look like the following for log configuration with -detail_level = 'summary':: +The following is an example of log output configuration with detail_level = +'summary' where `1-32073` is the connection identifier. 2018-03-17 11:39:09,877-pywbem.api.1-32073-Connection:1-32073 WBEMConnection(url='http://localhost', creds=None, default_namespace='root/cimv2') 2018-03-17 11:41:13,176-pywbem.api.1-32073-Request:1-32073 EnumerateClasses(ClassName=None, DeepInheritance=None, IncludeClassOrigin=None, IncludeQualifiers=None, LocalOnly=None, namespace=None) @@ -176,13 +203,11 @@ """ # noqa: E501 # pylint: enable=line-too-long -import logging - # NOTE: cannot use from pywbem import WBEMConnection because it is circular # import. -import pywbem +import pywbem.cim_operations -__all__ = ['define_loggers_from_string', +__all__ = ['configure_loggers_from_string', 'LOGGER_API_CALLS_NAME', 'LOGGER_HTTP_NAME', 'LOGGER_SIMPLE_NAMES', 'LOG_DESTINATIONS', 'DEFAULT_LOG_DETAIL_LEVEL', 'DEFAULT_LOG_DESTINATION', 'LOG_DETAIL_LEVELS'] @@ -218,10 +243,6 @@ #: objects(paths components in the objects) only the string representation #: of the path components is output. Otherwise the complete object #: representations are logged. -#: -#: * :class:`py:int` - All of the available data is formatted up to the size -#: defined. by the integer value for each log record. This option applies -#: to all of the logs generated. LOG_DETAIL_LEVELS = ['all', 'paths', 'summary'] #: Default log detail level string if none is supplied with a call to the @@ -234,50 +255,54 @@ DEFAULT_LOG_DESTINATION = 'none' -def define_loggers_from_string(log_config_str, log_filename=None, - connection=None): +def configure_loggers_from_string(log_configuration_str, log_filename=None, + connection=None): # pylint: disable=line-too-long """ - Configure the pywbem loggers defined by the input string in the syntax - documented with the `log_config_str`. This configures the defined logger - name with the destination and detail_level parameters defined by the dest - and detail level components of the string. + Configure the pywbem loggers from a log configuration string, and + optionally activate the loggers. This allows defining the complete pywbem + logger configuration from a single string. Parameters: - log_config_str (:term:`string`): Specifies the logger definitions + log_configuration_str (:term:`string`): Specifies the logger configuration with the following formats:: log_specs := log_spec [, log_spec ] log_spec := log_name ['=' [ dest ][":"[ detail_level ]]]] where: - log_name: Must be one of strings in the :data:`~pywbem._logging.LOG_SIMPLE_NAMES` list. + log_name: Simplified name for the logger. Must be one of strings in the :data:`~pywbem._logging.LOG_SIMPLE_NAMES` list. dest: Must be one of strings in the :data:`~pywbem._logging.LOG_DESTINATIONS` list. detail_level: Must be one of strings in the :data:`~pywbem._logging.LOG_DETAIL_LEVELS` list. log_filename (:term:`string`) - Optional string that defines the filename for output of logs - if the dest type is `file` + String that defines the filename for output of logs + if the dest type is `file`. If dest type is not `file` this parameter + is ignored. Raises: - ValueError: Generated if the syntax of the input string is invalid - or any of the components is not one of allowed strings. + ValueError: Generated if the syntax of the input string is invalid. Examples:: - api=stderr:summary # set cim operations logger for summary display + api=stderr:summary # set "pywbem.api" logger for summary display to + # stderr with summary level output - http=file # set http logger to send to file + http=file # set "pywbem.http" logger to output to file + # with default detail_level. - all=file:1000 # Set all loggers to output to a file with + api=stderr:summary # set "pywbem.api" logger to output to file + # with summary output level. + + all=file:1000 # Set both loggers to output to a file with # maximum of 1000 characters per log record - api=stderr,http=file # log api calls to stderr and http requests and - # responses to a file + api=stderr,http=file # log "pywbem.api" logger to output to stderr + # and "pywbem.http" to output a file """ # noqa: E501 - log_specs = log_config_str.split(',') + log_specs = log_configuration_str.split(',') for log_spec in log_specs: try: spec_split = log_spec.split("=", 1) @@ -304,7 +329,7 @@ def define_loggers_from_string(log_config_str, log_filename=None, if simple_log_name not in LOGGER_SIMPLE_NAMES: raise ValueError('Log string %s invalid. Log name %s not a valid ' 'pywbem logger name. Must be one of %s' % - (log_config_str, simple_log_name, + (log_configuration_str, simple_log_name, LOGGER_SIMPLE_NAMES)) detail_level = log_values[1] @@ -318,41 +343,6 @@ def define_loggers_from_string(log_config_str, log_filename=None, pywbem.WBEMConnection.configure_logger( simple_log_name, log_dest=log_values[0], - detail_level=log_values[1], + detail_level=detail_level, log_filename=log_filename, connection=connection) - - -def get_logger(logger_name): - """ - **Experimental:** *New in pywbem 0.11 as experimental.* - - Return a :class:`~py:logging.Logger` object with the specified name. - - A :class:`~py:logging.NullHandler` handler is added to the logger if it - does not have any handlers yet and if it is not the Python root logger. - This prevents the propagation of log requests up the Python logger - hierarchy, and therefore causes this package to be silent by default. - - This prevents the propagation of log requests up the Python logger - hierarchy, and therefore causes this package to be silent by default. - - Parameters - - logger_name (:term:`string`): - Name of the logger which must be one of the named defined in - pywbem for loggers used by pywbem. These names are structured - as prefix . - - Returns: - - :class:`~py:logging.Logger`: Logger defined by logger name. - - Raises: - - ValueError: The name is not one of the valid pywbem loggers. - """ - logger = logging.getLogger(logger_name) - if logger_name != '' and not logger.handlers: - logger.addHandler(logging.NullHandler()) - return logger diff --git a/pywbem/_recorder.py b/pywbem/_recorder.py index 8823b0d11..0d1b4a391 100644 --- a/pywbem/_recorder.py +++ b/pywbem/_recorder.py @@ -1,3 +1,4 @@ + # # This library is free software; you can redistribute it and/or # modify it under the terms of the GNU Lesser General Public @@ -37,10 +38,10 @@ from .cim_obj import CIMInstance, CIMInstanceName, CIMClass, CIMClassName, \ CIMProperty, CIMMethod, CIMParameter, CIMQualifier, \ - CIMQualifierDeclaration, NocaseDict + CIMQualifierDeclaration, NocaseDict, _ensure_unicode from .cim_types import CIMInt, CIMFloat, CIMDateTime from .exceptions import CIMError -from ._logging import LOGGER_API_CALLS_NAME, LOGGER_HTTP_NAME, get_logger +from ._logging import LOGGER_API_CALLS_NAME, LOGGER_HTTP_NAME if six.PY2: import codecs # pylint: disable=wrong-import-order @@ -512,38 +513,38 @@ class LogOperationRecorder(BaseOperationRecorder): """ **Experimental:** *New in pywbem 0.9 as experimental.* - A recorder that logs the WBEM operations to a set of named logs. - This recorder supports two named logs: + A recorder that logs the WBEM operations to a loggers based on the + Python logging package. + + This recorder supports two logger names: - * :attr:`~pywbem._logging.LOGGER_API_CALLS_NAME` - Logger at the level of - WBEM operation calls and returns + * :attr:`~pywbem._logging.LOGGER_API_CALLS_NAME` - Logs user-issued calls + to :class:`~pywbem.WBEMConnection` methods that drive WBEM operations + (see :ref:WBEM operations) and the responses before they are passed back + to the user - * :attr:`~pywbem._logging.LOGGER_HTTP_NAME` - Logger at the level of HTTP - requests and responses + * :attr:`~pywbem._logging.LOGGER_HTTP_NAME` - Logs HTTP requests and + responses. - This also implements a method to log information on each connection. + This also implements a method to log information on each + :class:`~pywbem.WBEMConnection` object created. - All logging calls are at the debug level. + All logging calls are at the debug level. """ - def __init__(self, conn_id=None, detail_levels=None): + def __init__(self, conn_id, detail_levels=None): """ Parameters: - conn_id ():) - If None, string that represents an id for a particular connection - that is used to build the name of each logger. if conn_id is not - `None` the logging calls are identified with the logger name - and the conn_id suffix (ex.pywbem.ops.1-2343) so that - each WBEMConnection could be logged with a separate logger. - - detail_level (:term:`integer` or :class:`py:dict`, or None): - The maximum size for each log entry, in Bytes. This is primarily to - limit response sizes since they could be enormous. - TODO - - If dict it is the detail level definition for each type + conn_id (:term:`connection id`): + String that represents an id for a particular connection + that is used to build the name of each logger. The logger names + are uniqueqly idenfified by the conn_id suffix to the logger name + (ex.pywbem.ops.1-2343) so that each WBEMConnection could be + logged with a separate logger. - If `None`, the log entry output size is not limited. + detail_levels ( :class:`py:dict`): + Dictionary identifying the detail_level for one or both of + the logger names. """ super(LogOperationRecorder, self).__init__() @@ -556,26 +557,26 @@ def __init__(self, conn_id=None, detail_levels=None): # build name for logger if conn_id: - self.apilogger = get_logger('%s.%s' % (LOGGER_API_CALLS_NAME, - conn_id)) + self.apilogger = self._get_logger('%s.%s' % (LOGGER_API_CALLS_NAME, + conn_id)) + self.httplogger = self._get_logger('%s.%s' % + (LOGGER_HTTP_NAME, conn_id)) else: - self.apilogger = get_logger(LOGGER_API_CALLS_NAME) + self.apilogger = self._get_logger(LOGGER_API_CALLS_NAME) + self.httplogger = self._get_logger(LOGGER_HTTP_NAME) self.detail_levels = self.set_detail_level(detail_levels) - if conn_id: - self.httplogger = get_logger('%s.%s' % (LOGGER_HTTP_NAME, conn_id)) - else: - self.httplogger = get_logger(LOGGER_HTTP_NAME) - def set_detail_level(self, detail_levels): """ - Sets the detail levels from the input dictionary. + Sets the detail levels from the input dictionary in detail_levels. """ if detail_levels is None: return None - self.api_detail_level = detail_levels.get('api', None) - self.http_detail_level = detail_levels.get('http', None) + if 'api' in detail_levels: + self.api_detail_level = detail_levels['api'] + if 'http' in detail_levels: + self.http_detail_level = detail_levels['http'] if isinstance(self.api_detail_level, int): self.api_maxlen = self.api_detail_level if isinstance(self.http_detail_level, int): @@ -646,10 +647,9 @@ def format_result(ret, max_len): if self.api_detail_level == 'summary': if isinstance(ret, list): if ret: - ret_type = type(ret[0]).__name__ if len(ret) else "" + ret_type = type(ret[0]).__name__ if ret else "" return 'list of %s; count=%s' % (ret_type, len(ret)) - else: - return 'Empty' + return 'Empty' else: result = ret result_fmt = '{0!r}'.format(result) @@ -677,7 +677,6 @@ def format_result(ret, max_len): return result_fmt if self.enabled and self.apilogger.isEnabledFor(logging.DEBUG): - if exc: # format exception # exceptions are always either all or reduced length result = format_result( @@ -741,13 +740,17 @@ def stage_http_request(self, conn_id, version, url, target, method, headers, header_str = ' '.join('{0}:{1!r}'.format(k, v) for k, v in headers.items()) if self.http_detail_level == 'summary': - payload = "" - elif self.http_maxlen and (len(payload) > self.http_maxlen): - payload = payload[:self.http_maxlen] + '...' + upayload = "" + elif isinstance(payload, six.binary_type): + upayload = payload.decode('utf-8') + else: + upayload = payload + if self.http_maxlen and (len(payload) > self.http_maxlen): + upayload = upayload[:self.http_maxlen] + '...' self.httplogger.debug('Request:%s %s %s %s %s %s\n %s', conn_id, method, target, version, url, - header_str, payload) + header_str, upayload) def stage_http_response1(self, conn_id, version, status, reason, headers): """Set response http info including headers, status, etc. """ @@ -774,25 +777,66 @@ def stage_http_response2(self, payload): header_str = '' if self.http_detail_level == 'summary': - payload = "" + upayload = "" elif self.http_maxlen and (len(payload) > self.http_maxlen): - payload = (payload[:self.http_maxlen] + '...') + upayload = (_ensure_unicode(payload[:self.http_maxlen]) + + '...') + else: + upayload = _ensure_unicode(payload) self.httplogger.debug('Response:%s %s:%s %s %s\n %s', self._http_response_conn_id, self._http_response_status, self._http_response_reason, self._http_response_version, - header_str, payload) + header_str, upayload) def record_staged(self): - """Not used for logging""" + """ + Not used for logging. The logs are output in the various + stage... methods methods + """ pass def record(self, pywbem_args, pywbem_result, http_request, http_response): """Not used for logging""" pass + @staticmethod + def _get_logger(logger_name): + """ + **Experimental:** *New in pywbem 0.11 as experimental.* + + Return a :class:`~py:logging.Logger` object with the specified name. + + A :class:`~py:logging.NullHandler` handler is added to the logger if it + does not have any handlers yet and if it is not the Python root logger. + This prevents the propagation of log requests up the Python logger + hierarchy, and therefore causes this package to be silent by default. + + This prevents the propagation of log requests up the Python logger + hierarchy, and therefore causes this package to be silent by default. + + Parameters + + logger_name (:term:`string`): + Name of the logger which must be one of the named defined in + pywbem for loggers used by pywbem. These names are structured + as prefix . + + Returns: + + :class:`~py:logging.Logger`: Logger defined by logger name. + + Raises: + + ValueError: The name is not one of the valid pywbem loggers. + """ + logger = logging.getLogger(logger_name) + if logger_name != '' and not logger.handlers: + logger.addHandler(logging.NullHandler()) + return logger + class TestClientRecorder(BaseOperationRecorder): """ diff --git a/pywbem/cim_operations.py b/pywbem/cim_operations.py index e0e297b2b..323db0413 100644 --- a/pywbem/cim_operations.py +++ b/pywbem/cim_operations.py @@ -304,7 +304,7 @@ class WBEMConnection(object): # pylint: disable=too-many-instance-attributes at the level of CIM-XML requests and responses. The :class:`~pywbem.LogOperationRecorder` class records the operations in the Python logging facility. This recorder is activated through the - `connect` parameter of :class:`~pywbem.WBEMConnection.configure_logger`. + `connection` parameter of :class:`~pywbem.WBEMConnection.configure_logger`. The :class:`~pywbem.TestClientRecorder` class records the operations in a file in the YAML format suitable for the test_client.py unit test program. Before version 0.11.0, pywbem supported only a single operation recorder @@ -1155,16 +1155,16 @@ def last_reply_len(self): @property def conn_id(self): """ - :term:`unicode string`: - String that is unique for each WBEMConnection object created across the - normal execution-life of the program using pywbem. The - `conn_id` is created when the WBEMConnection object is created and - remains constant throughout the life of that connection. + :term:`connection id`: + String that is unique for each :class:`~pywbem.WBEMConnection` object. + The `conn_id` is created when the :class:`~pywbem.WBEMConnection` object + is created and remains constant throughout the life of that connection. - `conn_id` is attached to each log entry output to uniquely identify - the WBEMConnection responsible for that log. It also part of - the log name for the API and CIM-XML logs so that logging could - be defined separately for different wbem connections. + `conn_id` is part of each log entry output to uniquely identify + the :class:`~pywbem.WBEMConnection` object responsible for that log. + It also part of the logger name for the "pywbem.api" and "pywbem.http" + loggers that create log entries so that logging can be defined + separately for different connections. """ return self._conn_id @@ -1221,58 +1221,61 @@ def configure_logger(cls, name, log_dest=DEFAULT_LOG_DESTINATION, log_filename=DEFAULT_LOG_DESTINATION, connection=None): """ - TODO - A log configuration helper function to configure a python logger that - logs user-issued calls to :class:`~pywbem.WBEMConnection` methods that - drive WBEM operations (see :ref:WBEM operations) and the responses - before they are passed back to the user. + A log configuration method to configure one or all python loggers to + log user-issued calls to :class:`~pywbem.WBEMConnection` methods that + drive WBEM operations (see :ref:`WBEM operations`) and the + responses/exceptions before they are passed back to the user. Parameters: name (:term:`string`): - Simple name for the log to be configured or `all` if all of the - :class:`~pywbem.WBEMConnection` loggers are to be configured. - This should be the simple name (ex. 'api'). This must be one the - named defined in :data:`~pywbem._logging.LOGGER_SIMPLE_NAMES` + Simple name (ex. 'api') for the logger to be configured or `all` if + all of the :class:`~pywbem.WBEMConnection` loggers are to + be configured. The value must be one of the named defined in + :data:`~pywbem._logging.LOGGER_SIMPLE_NAMES` log_dest (:term:`string`): String defining the destination for this log or None. If it is a :term:`string` defining one of the destinations defined in :data:`~pywbem._logging.LOG_DESTINATIONS` a Python logger is - configured for that destination. + configured for that destination including configuring a logging + handler, the message format and setting the log level to DEBUG. - If `None` a null logger is configured. + If `None` a logger with the Python Python NullHandler is configured. detail_level (:term:`string`, :class:`int` or None): Defines the level of detail contained in each log record created. If if is a :term:`string` it must be one of the key words that defines the level of detail to be output defined in - :data:`LOG_DETAIL_LEVELS`. + :data:`~pywbem._logging.LOG_DETAIL_LEVELS`. If it is a :class: `int` it defines the maximum size of the log - record record. + record record created. - If `None` it is set to the default level for that logger. + If `None` it is set to the default detail level for that logger. log_filename (:term:`string`): Filename to use as logging file if the log destination is `file`. - Ignored if log destination is not `file`. If value is `None` and - this is a ``file`` log, ValueError is raised. This parameter is - required if `log_dest` == 'file` + Ignored if log destination is not `file`. This parameter is + required if the dest parameter is `file`. connection (:class:`~pywbem.WBEMConnection` or :class:`py:bool`) - WBEMConnection object or to activate for logging. + WBEMConnection objects to activate for logging. - If `None` no WBEMConnection is activated. + If `None` no :class:`~pywbem.WBEMConnection` object is + activated. - If it is a :class:`py:bool` and `True` all subsequently created - WBEMconnection objects are activated for logging + If it is a :class:`py:bool` all subsequently created + :class:`~pywbem.WBEMConnection` objects will be affected. A value + of True will cause all subsequently created + :class:`~pywbem.WBEMConnection` objects to be activated for logging. + A value of False will cause all subsequently created not to be + activated. If it is a :class:`~pywbem.WBEMConnection` object, logging is - activated for that WBEMConnection object using the log - configuration previously defined or defined by this method. + activated for that :class:`~pywbem.WBEMConnection` object. Raises: @@ -1284,7 +1287,6 @@ def configure_logger(cls, name, log_dest=DEFAULT_LOG_DESTINATION, ' of the values in %s' % LOGGER_SIMPLE_NAMES) # if all, activate all loggers with any input parameters - # TODO clean up detail level defaults if name == 'all': if detail_level is None: detail_level = DEFAULT_LOG_DETAIL_LEVEL @@ -1312,13 +1314,13 @@ def configure_logger(cls, name, log_dest=DEFAULT_LOG_DESTINATION, handler = cls._configure_logger_handler(log_dest, log_filename) # process detail_level - detail_level = cls._validate_detail_level(detail_level) + detail_level = cls._configure_detail_level(detail_level) cls._activate_logger(logger_name, detail_level, handler, connection) @classmethod - def _validate_detail_level(cls, detail_level): + def _configure_detail_level(cls, detail_level): """ Validate the detail_level parameter and return it. This accepts a string or integer @@ -1336,7 +1338,6 @@ def _validate_detail_level(cls, detail_level): detail_level) elif detail_level is None: - # TODO fix this. Should be a more logical default # pylint: disable=redefined-variable-type detail_level = DEFAULT_LOG_DETAIL_LEVEL else: @@ -1371,16 +1372,18 @@ def _configure_logger_handler(cls, log_dest, log_filename): # pylint: disable=redefined-variable-type handler = logging.FileHandler(log_filename, encoding="UTF-8") handler.setFormatter(logging.Formatter(msg_format)) - else: - assert(log_dest == 'none') + elif log_dest == 'none' or log_dest is None: handler = logging.NullHandler() handler.setFormatter(None) + else: + raise ValueError('Invalid log dest parameter %s.' % log_dest) + return handler @classmethod def _activate_logger(cls, logger_name, detail_level, handler, connection): """ - Activate Log for defined connection. Links handler if defined to + Activate logger_name for defined connection. Links handler if defined to the logger iwht logger_name and if connection is defined activates the logger for the WBEMConnection object defined by connection and sets the detail level for the that WBEMConnection object. @@ -8026,7 +8029,7 @@ def InvokeMethod(self, MethodName, ObjectName, Params=None, **params): """ exc = None - result_tuple = None + result = None if self._operation_recorders: self.operation_recorder_reset() @@ -8054,7 +8057,7 @@ def InvokeMethod(self, MethodName, ObjectName, Params=None, **params): self.last_request_len, self.last_reply_len, self.last_server_response_time, exc) if self._operation_recorders: - self.operation_recorder_stage_result(result_tuple, exc) + self.operation_recorder_stage_result(result, exc) # # Query operations diff --git a/testsuite/run_cim_operations.py b/testsuite/run_cim_operations.py index 24f3e4827..332d17db5 100755 --- a/testsuite/run_cim_operations.py +++ b/testsuite/run_cim_operations.py @@ -146,7 +146,7 @@ def setUp(self, use_pull_operations=None): # if log set, enable the logger. if self.output_log: WBEMConnection.configure_logger( - 'all', log_dest='file', log_filename='run_cimoperations.log', + 'http', log_dest='file', log_filename='run_cimoperations.log', connection=self.conn) # enable saving of xml for display diff --git a/testsuite/test_cim_operations.py b/testsuite/test_cim_operations.py index e0449ae44..dd361fb96 100755 --- a/testsuite/test_cim_operations.py +++ b/testsuite/test_cim_operations.py @@ -118,14 +118,14 @@ def test_namespace_slashes_set(self): # pylint: disable=no-self-use def test_add_operation_recorder(self): # pylint: disable=no-self-use """Test addition of an operation recorder""" conn = WBEMConnection('http://localhost') - conn.add_operation_recorder(LogOperationRecorder()) + conn.add_operation_recorder(LogOperationRecorder('fake_conn_id')) # pylint: disable=protected-access assert len(conn._operation_recorders) == 1 def test_add_operation_recorders(self): # pylint: disable=no-self-use """Test addition of multiple operation recorders""" conn = WBEMConnection('http://localhost') - conn.add_operation_recorder(LogOperationRecorder()) + conn.add_operation_recorder(LogOperationRecorder('fake_conn_id')) tcr_fn = 'blah.yaml' tcr_file = MyTestClientRecorder.open_file(tcr_fn, 'a') conn.add_operation_recorder(MyTestClientRecorder(tcr_file)) @@ -140,12 +140,12 @@ def test_add_same_twice(self): # pylint: disable=no-self-use generates exception """ conn = WBEMConnection('http://localhost') - conn.add_operation_recorder(LogOperationRecorder()) + conn.add_operation_recorder(LogOperationRecorder('fake_conn_id')) # pylint: disable=protected-access assert len(conn._operation_recorders) == 1 with pytest.raises(ValueError): - conn.add_operation_recorder(LogOperationRecorder()) + conn.add_operation_recorder(LogOperationRecorder('fake_conn_id')) class TestGetRsltParams(object): diff --git a/testsuite/test_logging.py b/testsuite/test_logging.py index 9c3829224..10f630bdf 100755 --- a/testsuite/test_logging.py +++ b/testsuite/test_logging.py @@ -16,7 +16,8 @@ # License along with this program; if not, write to the Free Software # Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. """ -Unit test logging functionality in _logging.py +Unit test logging functionality in _logging.py and +the WBEMConnection.configure_logger methods """ @@ -42,7 +43,7 @@ from testfixtures import LogCapture, log_capture, compare from pywbem import WBEMConnection -from pywbem._logging import get_logger, define_loggers_from_string, \ +from pywbem._logging import configure_loggers_from_string, \ LOGGER_API_CALLS_NAME, LOGGER_HTTP_NAME VERBOSE = False @@ -54,13 +55,28 @@ TEST_OUTPUT_LOG = '%s/%s' % (SCRIPT_DIR, LOG_FILE_NAME) -class UnitLoggingTests(unittest.TestCase): +class BaseLoggingTest(unittest.TestCase): + """ + Methods required by all tests + """ + @staticmethod + def _get_logger(logger_name): + """Duplicate method local to recorder""" + logger = logging.getLogger(logger_name) + if logger_name != '' and not logger.handlers: + logger.addHandler(logging.NullHandler()) + return logger + + +class UnitLoggingTests(BaseLoggingTest): """Base class for logging unit tests""" def logger_validate(self, log_name, log_dest, detail_level, log_filename=None): """ - Test for correct definition of one logger + Test for correct definition of one logger. Creates the logger and + tests the logger parameters against expected results. This does not + create any logs. """ if log_name == 'all': self.logger_validate('api', log_dest, detail_level, @@ -70,9 +86,9 @@ def logger_validate(self, log_name, log_dest, detail_level, else: if log_name == 'api': - logger = get_logger(LOGGER_API_CALLS_NAME) + logger = self._get_logger(LOGGER_API_CALLS_NAME) elif log_name == 'http': - logger = get_logger(LOGGER_HTTP_NAME) + logger = self._get_logger(LOGGER_HTTP_NAME) else: self.fail('Input error. log_name %s ' % log_name) @@ -91,10 +107,10 @@ def logger_validate(self, log_name, log_dest, detail_level, else: self.fail('No logger defined') - def define_logger_test(self, log_name, log_dest=None, detail_level=None, - log_filename=None, error=None): + def configure_logger_test(self, log_name, log_dest=None, detail_level=None, + log_filename=None, error=None): """ - Unified test function for the define_logger function + Unified test function for the configure_logger function """ if error: try: @@ -119,25 +135,26 @@ def loggers_from_string_test(self, param, expected_result, log_file=None, # logging handlers are static. We must clear them between tests # Remove any handlers from loggers for this test - api_logger = get_logger(LOGGER_API_CALLS_NAME) + api_logger = self._get_logger(LOGGER_API_CALLS_NAME) api_logger.handlers = [] - http_logger = get_logger(LOGGER_HTTP_NAME) + http_logger = self._get_logger(LOGGER_HTTP_NAME) http_logger.handlers = [] - if connection_defined: - conn = WBEMConnection('http:/blah') + # TODO for test below not yet implemented + # if connection_defined: + # conn = WBEMConnection('http:/blah') if expected_result == 'error': try: - define_loggers_from_string(param, log_filename=log_file) + configure_loggers_from_string(param, log_filename=log_file) self.fail('Exception expected') except ValueError: pass else: - define_loggers_from_string(param, log_filename=log_file) + configure_loggers_from_string(param, log_filename=log_file) - api_logger = get_logger(LOGGER_API_CALLS_NAME) - http_logger = get_logger(LOGGER_HTTP_NAME) + api_logger = self._get_logger(LOGGER_API_CALLS_NAME) + http_logger = self._get_logger(LOGGER_HTTP_NAME) if 'level' in expected_result: level = expected_result['level'] if level[0]: @@ -161,14 +178,14 @@ def loggers_from_string_test(self, param, expected_result, log_file=None, detail_level = expected_result['detail'] if connection_defined: # TODO add test for when connection param exists - print(conn) + # need to get to recorder and test detail level + pass + # print(conn) else: if detail_level[0]: details = WBEMConnection._log_config_dict self.assertTrue(details['api']) == detail_level[0] - # try to remove any created log file. - # remove handlers from our loggers. for h in api_logger.handlers: api_logger.removeHandler(h) @@ -187,19 +204,19 @@ def loggers_from_string_test(self, param, expected_result, log_file=None, class TestLoggersFromString(UnitLoggingTests): """ - Test the define_loggers_from_string and define_logger functions. Some of - the logging configuration methods are in WBEMConnection + Test the configure_loggers_from_string and WBEMConnection.configure_logger + functions. Some of the logging configuration methods are in WBEMConnection """ def test_comp_only(self): - """Test all string""" + """'Test all' string""" self.loggers_from_string_test('all', {'level': (0, 0), 'handler': (logging.NullHandler, logging.NullHandler), 'detail': (None, None)}) def test_comp_only2(self): - """Test all= string""" + """'Test all=' string""" param = 'all=' self.loggers_from_string_test(param, {'level': (0, 0), 'handler': (logging.NullHandler, @@ -213,6 +230,26 @@ def test_complete1(self): logging.FileHandler)}, log_file='blah.log') + def test_complete2(self): + """Test all=file:summary string""" + param = 'all=file:summary' + self.loggers_from_string_test(param, {'level': (10, 10), + 'handler': (logging.FileHandler, + logging.FileHandler), + 'detail': ('summary', 'summary')}, + + log_file='blah.log') + + def test_complete3(self): + """Test all=file:summary string""" + param = 'all=file:10' + self.loggers_from_string_test(param, {'level': (10, 10), + 'handler': (logging.FileHandler, + logging.FileHandler), + 'detail': (10, 10)}, + + log_file='blah.log') + def test_multiple1(self): """Test api=file:min,http=file:all string""" param = 'api=file,http=file:all' @@ -246,54 +283,58 @@ def test_empty(self): class TestDefineLogger(UnitLoggingTests): - """ Test the define_logger method.""" + """ Test the configure_logger method.""" - def test_define_single_logger1(self): + def test_configue_single_logger1(self): """ Create a simple logger """ - self.define_logger_test('api', 'file', detail_level='all', - log_filename=TEST_OUTPUT_LOG) + self.configure_logger_test('api', 'file', detail_level='all', + log_filename=TEST_OUTPUT_LOG) def test_create_single_logger2(self): """ Create a simple logger from detailed parameter input """ - self.define_logger_test('http', 'file', detail_level='all', - log_filename=TEST_OUTPUT_LOG) + self.configure_logger_test('http', 'file', detail_level='all', + log_filename=TEST_OUTPUT_LOG) def test_create_single_logger3(self): """ Create a simple logger from detailed parameter input """ - self.define_logger_test('http', 'stderr', detail_level='all', - log_filename=TEST_OUTPUT_LOG) + self.configure_logger_test('http', 'stderr', detail_level='all', + log_filename=TEST_OUTPUT_LOG) def test_create_single_logger4(self): """ Create a simple logger from detailed parameter input """ - self.define_logger_test('all', 'stderr', detail_level='all', - log_filename=TEST_OUTPUT_LOG) + self.configure_logger_test('all', 'stderr', detail_level='all', + log_filename=TEST_OUTPUT_LOG) def test_create_single_logger5(self): """ Create a simple logger from detailed parameter input """ - self.define_logger_test('all', 'stderr', detail_level='all', - log_filename=TEST_OUTPUT_LOG) + self.configure_logger_test('all', 'stderr', detail_level='all', + log_filename=TEST_OUTPUT_LOG) def test_create_single_loggerEr1(self): """ Create a simple logger from detailed parameter input """ - self.define_logger_test('api', 'blah', detail_level='all', error=True) - self.define_logger_test('http', 'blah', detail_level='all', error=True) - self.define_logger_test('api', 'blah', detail_level='al', error=True) - self.define_logger_test('http', 'blah', detail_level='al', error=True) + self.configure_logger_test('api', 'blah', detail_level='all', + error=True) + self.configure_logger_test('http', 'blah', detail_level='all', + error=True) + self.configure_logger_test('api', 'blah', detail_level='al', + error=True) + self.configure_logger_test('http', 'blah', detail_level='al', + error=True) -class BaseLoggingTests(unittest.TestCase): +class BaseLoggingExecutionTests(BaseLoggingTest): """Base class for logging unit tests""" def tearDown(self): @@ -303,16 +344,16 @@ def tearDown(self): os.remove(TEST_OUTPUT_LOG) -class TestLoggerOutput(BaseLoggingTests): +class TestLoggerOutput(BaseLoggingExecutionTests): """Test output from logging""" @log_capture() def test_log_output(self, l): # pylint: disable=blacklisted-name test_input = 'all=file' - define_loggers_from_string(test_input, TEST_OUTPUT_LOG) + configure_loggers_from_string(test_input, TEST_OUTPUT_LOG) - my_logger = get_logger(LOGGER_API_CALLS_NAME) + my_logger = self._get_logger(LOGGER_API_CALLS_NAME) self.assertNotEqual(my_logger, None, 'Valid named logger %s expected.' diff --git a/testsuite/test_recorder.py b/testsuite/test_recorder.py index ba0919a71..7790d2151 100755 --- a/testsuite/test_recorder.py +++ b/testsuite/test_recorder.py @@ -14,6 +14,7 @@ import os import os.path import logging +import logging.handlers from io import open as _open import unittest2 as unittest # we use assertRaises(exc) introduced in py27 @@ -117,6 +118,34 @@ def create_ciminstancepaths(self): paths.append(self.create_ciminstancename()) return paths + def create_method_params(self): + """Create a set of method params to be used in InvokeMethodTests.""" + dt_now = CIMDateTime.now() + obj_name = self.create_ciminstancename() + + dt = datetime(year=2016, month=3, day=31, hour=19, minute=30, + second=40, microsecond=654321, + tzinfo=MinutesFromUTC(120)) + cim_dt = CIMDateTime(dt) + + params = [('StringParam', 'Spotty'), + ('Uint8', Uint8(1)), + ('Sint8', Sint8(2)), + ('Uint16', Uint16(3)), + ('Sint16', Sint16(3)), + ('Uint32', Uint32(4)), + ('Sint32', Sint32(5)), + ('Uint64', Uint64(6)), + ('Sint64', Sint64(7)), + ('Real32', Real32(8)), + ('Real64', Real64(9)), + ('Bool', True), + ('DTN', dt_now), + ('DTF', cim_dt), + ('DTI', CIMDateTime(timedelta(60))), + ('Ref', obj_name)] + return params + class ClientRecorderTests(BaseRecorderTests): """ @@ -307,25 +336,10 @@ def test_invoke_method(self): Each test emulated a single cim operation with fixed data to create the input for the yaml, create the yaml, and test the result """ - obj_name = self.create_ciminstancename() - - dt_now = CIMDateTime.now() - - params = [('StringParam', 'Spotty'), - ('Uint8', Uint8(1)), - ('Sint8', Sint8(2)), - ('Uint16', Uint16(3)), - ('Sint16', Sint16(3)), - ('Uint32', Uint32(4)), - ('Sint32', Sint32(5)), - ('Uint64', Uint64(6)), - ('Sint64', Sint64(7)), - ('Real32', Real32(8)), - ('Real64', Real64(9)), - ('Bool', True), - ('DTN', dt_now), - ('DTI', timedelta(60)), - ('Ref', obj_name)] + params = self.create_method_params() + in_params_dict = OrderedDict(params) + obj_name = in_params_dict['Ref'] + dt_now = str(in_params_dict['DTN']) self.test_recorder.stage_pywbem_args(method='InvokeMethod', MethodName='Blah', @@ -347,23 +361,30 @@ def test_invoke_method(self): operation = pywbem_request['operation'] self.assertEqual(operation['pywbem_method'], 'InvokeMethod') self.assertEqual(operation['MethodName'], 'Blah') - - param_dict = dict(params) - self.assertEqual(param_dict['StringParam'], 'Spotty') - self.assertEqual(param_dict['Uint8'], 1) - self.assertEqual(param_dict['Sint8'], 2) - self.assertEqual(param_dict['Uint16'], 3) - self.assertEqual(param_dict['Sint16'], 3) - self.assertEqual(param_dict['Uint32'], 4) - self.assertEqual(param_dict['Sint32'], 5) - self.assertEqual(param_dict['Uint64'], 6) - self.assertEqual(param_dict['Sint64'], 7) - self.assertEqual(param_dict['Real32'], 8) - self.assertEqual(param_dict['Real64'], 9) - self.assertEqual(param_dict['Bool'], True) - self.assertEqual(param_dict['DTN'], dt_now) - self.assertEqual(param_dict['DTI'], timedelta(60)) - self.assertEqual(param_dict['Ref'], obj_name) + out_params_dict = OrderedDict(operation['Params']) + + self.assertEqual(len(in_params_dict), len(out_params_dict)) + + self.assertEqual(out_params_dict['StringParam'], 'Spotty') + self.assertEqual(out_params_dict['Uint8'], 1) + self.assertEqual(out_params_dict['Sint8'], 2) + self.assertEqual(out_params_dict['Uint16'], 3) + self.assertEqual(out_params_dict['Sint16'], 3) + self.assertEqual(out_params_dict['Uint32'], 4) + self.assertEqual(out_params_dict['Sint32'], 5) + self.assertEqual(out_params_dict['Uint64'], 6) + self.assertEqual(out_params_dict['Sint64'], 7) + self.assertEqual(out_params_dict['Real32'], 8) + self.assertEqual(out_params_dict['Real64'], 9) + self.assertEqual(out_params_dict['Bool'], True) + self.assertEqual(out_params_dict['DTN'], dt_now) + self.assertEqual(out_params_dict['DTI'], + str(CIMDateTime(timedelta(60)))) + # TODO fix the following. Currently it fails with: + # AssertionError: CIMIn[16 chars]name={'classname': 'CIM_Foo', + # 'keybindings': {[132 chars]None) != CIMIn[16 chars]name=u'CIM_Foo', + # keybindings=NocaseDict([('Chi[55 chars]com') + # self.assertEqual(CIMInstanceName(out_params_dict['Ref']), obj_name) def test_get_instance(self): """ @@ -505,16 +526,17 @@ def recorder_setup(self, detail_level=None): detail_level=detail_level, log_filename=TEST_OUTPUT_LOG) - # define an attribute that is a single LogOperationRecorder to be used - # in some of the tests + # Define an attribute that is a single LogOperationRecorder to be used + # in some of the tests. Note that if detail_level is dict it is used + # directly. + if isinstance(detail_level, (six.string_types, six.integer_types)): + detail_level = {'api': detail_level, 'http': detail_level} - details = {'api': detail_level, 'http': detail_level} # pylint: disable=attribute-defined-outside-init - self.test_recorder = LogOperationRecorder(conn_id='test_id', - detail_levels=details) - # Set a conn id into the connection. Saves testing the connection # log for each test. + self.test_recorder = LogOperationRecorder('test_id', + detail_levels=detail_level) # pylint: disable=protected-access self.test_recorder.reset() self.test_recorder.enable() @@ -1217,7 +1239,6 @@ def build_http_response(self): '\n' '\n' ')\n') - # body = body.decode('utf-8') headers = OrderedDict([ ('Content-type', 'application/xml; charset="utf-8"'), ('Content-length', str(len(body)))]) @@ -1509,8 +1530,6 @@ def test_openenuminstances_result_all(self, lc): self.test_recorder.stage_pywbem_result(result_tuple, exc) - # TODO why the single quote around the [] below??? - lc.check( ("pywbem.api.test_id", "DEBUG", "Request:test_id OpenEnumerateInstances(ClassName='CIM_Foo', " @@ -1625,6 +1644,171 @@ def test_associators_result_exception(self, lc): ('pywbem.api.test_id', 'DEBUG', "Exception:test_id None('CIMError(6...)"),) + @log_capture() + def test_invokemethod_int(self, lc): + """Test invoke method log""" + self.recorder_setup(detail_level=11) + + obj_name = self.create_ciminstancename() + return_val = 0 + params = [('StringParam', 'Spotty'), + ('Uint8', Uint8(1)), + ('Sint8', Sint8(2))] + + self.test_recorder.stage_pywbem_args(method='InvokeMethod', + MethodName='Blah', + ObjectName=obj_name, + Params=OrderedDict(params)) + + self.test_recorder.stage_pywbem_result((return_val, params), + None) + + lc.check( + ('pywbem.api.test_id', 'DEBUG', + "Request:test_id InvokeMethod(MethodName=...)"), + ('pywbem.api.test_id', + 'DEBUG', + "Return:test_id InvokeMethod((0, [('Stri...)")) + + @log_capture() + def test_invokemethod_summary(self, lc): + """Test invoke method log""" + self.recorder_setup(detail_level='summary') + + obj_name = self.create_ciminstancename() + return_val = 0 + params = [('StringParam', 'Spotty'), + ('Uint8', Uint8(1)), + ('Sint8', Sint8(2))] + + self.test_recorder.stage_pywbem_args(method='InvokeMethod', + MethodName='Blah', + ObjectName=obj_name, + Params=OrderedDict(params)) + + self.test_recorder.stage_pywbem_result((return_val, params), + None) + + req = "Request:test_id InvokeMethod(MethodName='Blah', " \ + "ObjectName=CIMInstanceName(classname=u'CIM_Foo', " \ + "keybindings=NocaseDict([('Chicken', u'Ham')]), namespace=" \ + "u'root/cimv2', host=u'woot.com'), Params=OrderedDict(" \ + "[('StringParam', 'Spotty'), ('Uint8', Uint8(cimtype='uint8', " \ + "minvalue=0, maxvalue=255, 1)), ('Sint8', Sint8(cimtype=" \ + "'sint8', minvalue=-128, maxvalue=127, 2))]))" + + if six.PY3: + req = req.replace("u'", "'") + + lc.check( + ('pywbem.api.test_id', 'DEBUG', req), + ('pywbem.api.test_id', + 'DEBUG', + "Return:test_id InvokeMethod((0, [('StringParam', 'Spotty'), " + "('Uint8', Uint8(cimtype='uint8', minvalue=0, maxvalue=255, 1)), " + "('Sint8', Sint8(cimtype='sint8', minvalue=-128, maxvalue=127, 2)" + ")]))")) + + # TODO add tests for all for invoke method. + + +class TestExternLoggerDef(BaseLogOperationRecorderTests): + """ Test configuring loggers above level of our loggers""" + @log_capture() + def test_root_logger(self, lc): + """ + Create a logger using logging.basicConfig and generate logs + """ + logging.basicConfig(filename=TEST_OUTPUT_LOG, level=logging.DEBUG) + detail_level = 10 + WBEMConnection.configure_logger('api', + detail_level=10) + + detail_level = {'api': detail_level, 'http': detail_level} + + self.test_recorder = LogOperationRecorder('test_id', + detail_levels=detail_level) + + # We don't activate because we are not using wbemconnection, just + # the recorder calls. + self.test_recorder.stage_pywbem_args( + method='EnumerateInstanceNames', + ClassName='CIM_Foo', + LocalOnly=True, + IncludeQualifiers=True, + IncludeClassOrigin=True, + PropertyList=['propertyblah', 'blah2']) + + exc = None + inst_name = self.create_ciminstancename() + self.test_recorder.stage_pywbem_result([inst_name, inst_name], exc) + + lc.check( + ("pywbem.api.test_id", "DEBUG", + "Request:test_id EnumerateInstanceNames(ClassName=...)"), + ('pywbem.api.test_id', 'DEBUG', + 'Return:test_id EnumerateInstanceNames([CIMInstan...)')) + + @unittest.skip("Test unreliable exception not always the same") + @log_capture() + def test_pywbem_logger(self, lc): + """ + """ + logger = logging.getLogger('pywbem') + handler = logging.FileHandler(TEST_OUTPUT_LOG) + handler.setLevel(logging.DEBUG) + formatter = logging.Formatter('%(asctime)s - %(name)s - %(message)s') + handler.setFormatter(formatter) + logger.addHandler(handler) + + WBEMConnection.configure_logger('api', detail_level='summary', + connection=True) + try: + conn = WBEMConnection('http://blah', timeout=1) + + conn.GetClass('blah') + except Exception: + pass + + conn_id = conn.conn_id + + api_exp_log_id = 'pywbem.api.%s' % conn_id + http_exp_log_id = 'pywbem.http.%s' % conn_id + exc = "Exception:%s GetClass('ConnectionError(Socket error: " \ + "[Errno 113] No route to host)')" % conn_id + # pylint: disable=line-too-long + + con = "Connection:%s WBEMConnection(url=u'http://blah', creds=None," \ + " conn_id=%s, default_namespace=u'root/cimv2', x509=None, " \ + "verify_callback=None, ca_certs=None, no_verification=False, " \ + "timeout=1, use_pull_operations=False, stats_enabled=False, " \ + "recorders=['LogOperationRecorder'])" % (conn_id, conn_id) + + req = "Request:%s GetClass(ClassName='blah', IncludeClassOrigin=None," \ + " IncludeQualifiers=None, LocalOnly=None, PropertyList=None, " \ + "namespace=None)" % conn_id + hreq = u"Request:%s POST /cimom 11 http://blah CIMOperation:" \ + "'MethodCall' " \ + "CIMMethod:'GetClass' CIMObject:u'root/cimv2'\n" \ + '\n' \ + '' \ + '' \ + '' \ + '' \ + '' % \ + conn_id + + lc.check( + (api_exp_log_id, 'DEBUG', con), + (api_exp_log_id, 'DEBUG', req), + (http_exp_log_id, 'DEBUG', hreq), + (api_exp_log_id, 'DEBUG', exc) + ) + if __name__ == '__main__': unittest.main() diff --git a/wbemcli.py b/wbemcli.py index 728afcbe8..c6f256049 100644 --- a/wbemcli.py +++ b/wbemcli.py @@ -113,7 +113,7 @@ from pywbem._logging import LOG_DESTINATIONS, \ LOG_DETAIL_LEVELS, LOGGER_SIMPLE_NAMES, DEFAULT_LOG_DETAIL_LEVEL, \ - DEFAULT_LOG_DESTINATION, define_loggers_from_string + DEFAULT_LOG_DESTINATION, configure_loggers_from_string from pywbem import __version__ # Connection global variable. Set by remote_connection and use @@ -3178,11 +3178,13 @@ def _main(): action='store', default=None, help='R|Log_spec defines characteristics of the various named\n' 'loggers. It is the form:\n COMP=[DEST[:DETAIL]] where:\n' - ' COMP: Logger component name:[{c}].\n' - ' (Default={cd})\n' - ' DEST: Destination for component:[{d}].\n' - ' (Default={dd})\n' - ' DETAIL: Detail Level to log: [{dl}].\n' + ' COMP: Logger component name:[{c}].\n' + ' (Default={cd})\n' + ' DEST: Destination for component:[{d}].\n' + ' (Default={dd})\n' + ' DETAIL: Detail Level to log: [{dl}] or\n' + ' an integer that defines the maximum length of\n' + ' of each log record.\n' ' (Default={dll})\n' # pylint: disable=bad-continuation .format(c='|'.join(LOGGER_SIMPLE_NAMES), @@ -3209,7 +3211,7 @@ def _main(): CONN = _remote_connection(args.server, args, argparser) if args.log: - define_loggers_from_string(args.log, WBEMCLI_LOG_FILENAME, CONN) + configure_loggers_from_string(args.log, WBEMCLI_LOG_FILENAME, CONN) # Determine file path of history file home_dir = '.'