From 41b8bebe2aaffd7cd664886ac83c2661839b7c61 Mon Sep 17 00:00:00 2001 From: kschopmeyer Date: Fri, 23 Mar 2018 08:01:21 -0500 Subject: [PATCH] Clean up from Andy's Comments 1. Rewrite much of _logging.py docstring per comments and discussion 2.move get_logger to internal method of recorder 3. Rewrite some of docstring for WBEMConnection.configure_logger 4. Add tests. Fix utf-8 decode in stage_request a. Added a test for log invoke method. Note that to do this I modified the TestClient... InvokeMethod test to create a common method that creates params. 5. Made conn_id param in LogOperationRecorder a required parameter. Should always have been. 6. Added utf-8 decode to Log of stage_request. It was failing on CreateInstance with utf-8 issue 7. Added term for connection id Andy's comments fixed from 30 March 2018 Add new tests to help answer Andy's questions about root logger, etc. Added new test for invokemethod and fixed the fact that the original test did not test result. Added test in _logging for detail_level as integer. Fixed error in cim_operation.py where recorder was broken for invokemethod result. It had two names for the result but was using the wrong one. Fix issue in configure_from_string. --- docs/appendix.rst | 8 + docs/client/logging.rst | 7 - pywbem/_logging.py | 324 +++++++++++++++---------------- pywbem/_recorder.py | 140 ++++++++----- pywbem/cim_operations.py | 87 +++++---- testsuite/run_cim_operations.py | 2 +- testsuite/test_cim_operations.py | 8 +- testsuite/test_logging.py | 129 +++++++----- testsuite/test_recorder.py | 274 +++++++++++++++++++++----- wbemcli.py | 16 +- 10 files changed, 630 insertions(+), 365 deletions(-) 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 = '.'