Add tests for http request log

Add tests for http request log with the various detail_level options

Fix issues found in http log unit test

1. Remove DEFAULT_HTTP_LOG_DETAIL and DEFAULT_API_LOG_DETAIL_LEVEL. This
means that there is a single default for both logs.  This makes life
easier for things like help with cmd lines.

2. Fix issue in stage_http_response with detail_level

3. Add unit tests for stage_http_request and stage_http_response*

pywbem/_logging.py

@@ -185,7 +185,6 @@
 __all__ = ['define_loggers_from_string',
            'LOGGER_API_CALLS_NAME', 'LOGGER_HTTP_NAME', 'LOGGER_SIMPLE_NAMES',
            'LOG_DESTINATIONS', 'DEFAULT_LOG_DETAIL_LEVEL',
-           'DEFAULT_API_LOG_DEFAULT_LEVEL', 'DEFAULT_HTTP_LOG_DETAIL_LEVEL',
            'DEFAULT_LOG_DESTINATION', 'LOG_DETAIL_LEVELS']
 
 #: Name of logger for logging user-issued calls to
@@ -228,8 +227,6 @@
 #: Default log detail level string if none is supplied with a call to the
 #: :class:`pywbem._logging.PywbemLoggers` methods that configure pywbem named
 #: loggers
-DEFAULT_HTTP_LOG_DETAIL_LEVEL = 'all'
-DEFAULT_API_LOG_DEFAULT_LEVEL = 'summary'
 DEFAULT_LOG_DETAIL_LEVEL = 'all'
 
 #: Default log destination if none is defined when named loggers are

pywbem/_recorder.py

@@ -740,14 +740,14 @@ 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':
-                show_payload = ""
-            else:
-                show_payload = payload
+                payload = ""
+            elif self.http_maxlen and (len(payload) > self.http_maxlen):
+                payload = payload[:self.http_maxlen] + '...'
+
             self.httplogger.debug('Request:%s %s %s %s %s %s\n    %s',
                                   conn_id, method, target, version, url,
-                                  header_str, show_payload)
+                                  header_str, payload)
 
     def stage_http_response1(self, conn_id, version, status, reason, headers):
         """Set response http info including headers, status, etc. """
@@ -773,23 +773,17 @@ def stage_http_response2(self, payload):
             else:
                 header_str = ''
 
-            # format the payload possibly with max size limit
-            payload = '%r' % payload.decode('utf-8')
-
             if self.http_detail_level == 'summary':
-                display_payload = ""
-            else:
-                if self.http_maxlen and (len(payload) > self.http_maxlen):
-                    display_payload = (payload[:self.http_maxlen] + '...')
-                else:
-                    display_payload = payload
+                payload = ""
+            elif self.http_maxlen and (len(payload) > self.http_maxlen):
+                payload = (payload[:self.http_maxlen] + '...')
 
             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, display_payload)
+                                  header_str, payload)
 
     def record_staged(self):
         """Not used for logging"""

pywbem/cim_operations.py

@@ -155,8 +155,7 @@
 from .exceptions import ParseError, CIMError
 from ._statistics import Statistics
 from ._recorder import LogOperationRecorder
-from ._logging import DEFAULT_LOG_DESTINATION, DEFAULT_HTTP_LOG_DETAIL_LEVEL, \
-    DEFAULT_API_LOG_DEFAULT_LEVEL, DEFAULT_LOG_DETAIL_LEVEL, \
+from ._logging import DEFAULT_LOG_DESTINATION, DEFAULT_LOG_DETAIL_LEVEL, \
     LOG_DESTINATIONS, LOGGER_API_CALLS_NAME, \
     LOGGER_HTTP_NAME, LOG_DETAIL_LEVELS, LOGGER_SIMPLE_NAMES
 
@@ -1301,11 +1300,11 @@ def configure_logger(cls, name, log_dest=DEFAULT_LOG_DESTINATION,
             if name == 'api':
                 logger_name = LOGGER_API_CALLS_NAME
                 if detail_level is None:
-                    detail_level = DEFAULT_API_LOG_DEFAULT_LEVEL
+                    detail_level = DEFAULT_LOG_DETAIL_LEVEL
             elif name == 'http':
                 logger_name = LOGGER_HTTP_NAME
                 if detail_level is None:
-                    detail_level = DEFAULT_HTTP_LOG_DETAIL_LEVEL
+                    detail_level = DEFAULT_LOG_DETAIL_LEVEL
             else:
                 assert False
 
@@ -1370,7 +1369,7 @@ def _configure_logger_handler(cls, log_dest, log_filename):
                 raise ValueError('Filename required if log destination '
                                  'is "file"')
             # pylint: disable=redefined-variable-type
-            handler = logging.FileHandler(log_filename)
+            handler = logging.FileHandler(log_filename, encoding="UTF-8")
             handler.setFormatter(logging.Formatter(msg_format))
         else:
             assert(log_dest == 'none')

testsuite/test_recorder.py

@@ -15,6 +15,7 @@
 import os.path
 import logging
 from io import open as _open
+
 import unittest2 as unittest  # we use assertRaises(exc) introduced in py27
 import six
 from testfixtures import LogCapture, log_capture
@@ -116,12 +117,6 @@ def create_ciminstancepaths(self):
         paths.append(self.create_ciminstancename())
         return paths
 
-    def request_html(self):
-        pass
-
-    def response_html(self):
-        pass
-
 
 class ClientRecorderTests(BaseRecorderTests):
     """
@@ -501,23 +496,19 @@ class BaseLogOperationRecorderTests(BaseRecorderTests):
     """
     def recorder_setup(self, detail_level=None):
         """Setup the recorder for a defined max output size"""
-        if detail_level in ['paths', 'summary']:
-            http_detail_level = 'all'
-        else:
-            http_detail_level = detail_level
 
         WBEMConnection.configure_logger('api', log_dest='file',
                                         detail_level=detail_level,
                                         log_filename=TEST_OUTPUT_LOG)
 
         WBEMConnection.configure_logger('http', log_dest='file',
-                                        detail_level=http_detail_level,
+                                        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
 
-        details = {'api': detail_level, 'http': 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)
@@ -1086,6 +1077,227 @@ def test_stage_instance_result_pull(self, lc):
 
         lc.check(("pywbem.api.test_id", "DEBUG", result))
 
+    def build_http_request(self):
+        """
+        Build an http request for the following tests
+        """
+        headers = OrderedDict([
+            ('CIMOperation', 'MethodCall'),
+            ('CIMMethod', 'GetInstance'),
+            ('CIMObject', 'root/cimv2')])
+        url = 'http://blah'
+        method = 'POST'
+        target = '/cimom'
+
+        payload = (
+            '<?xml version="1.0" encoding="utf-8" ?>\n'
+            '<CIM CIMVERSION="2.0" DTDVERSION="2.0">\n'
+            '<MESSAGE ID="1001" PROTOCOLVERSION="1.0">\n'
+            '<SIMPLEREQ>\n'
+            '<IMETHODCALL NAME="GetInstance">\n'
+            '<LOCALNAMESPACEPATH>\n'
+            '<NAMESPACE NAME="root"/>\n'
+            '<NAMESPACE NAME="cimv2"/>\n'
+            '</LOCALNAMESPACEPATH>\n'
+            '<IPARAMVALUE NAME="InstanceName">\n'
+            '<INSTANCENAME CLASSNAME="PyWBEM_Person">\n'
+            '<KEYBINDING NAME="Name">\n'
+            '<KEYVALUE VALUETYPE="string">Fritz</KEYVALUE>\n'
+            '</KEYBINDING>\n'
+            '</INSTANCENAME>\n'
+            '</IPARAMVALUE>\n'
+            '<IPARAMVALUE NAME="LocalOnly">\n'
+            '<VALUE>FALSE</VALUE>\n'
+            '</IPARAMVALUE>\n'
+            '</IMETHODCALL>\n'
+            '</SIMPLEREQ>\n'
+            '</MESSAGE>\n'
+            '</CIM>)')
+
+        return url, target, method, headers, payload
+
+    @log_capture()
+    def test_stage_http_request_all(self, lc):
+        """Test stage of http_request log with detail_level='all'"""
+        self.recorder_setup(detail_level='all')
+        url, target, method, headers, payload = self.build_http_request()
+        self.test_recorder.stage_http_request('test_id', 11, url, target,
+                                              method, headers, payload)
+
+        result = (
+            "Request:test_id POST /cimom 11 http://blah CIMOperation:"
+            "'MethodCall' "
+            "CIMMethod:'GetInstance' CIMObject:'root/cimv2'\n"
+            '    <?xml version="1.0" encoding="utf-8" ?>\n'
+            '<CIM CIMVERSION="2.0" DTDVERSION="2.0">\n'
+            '<MESSAGE ID="1001" PROTOCOLVERSION="1.0">\n'
+            '<SIMPLEREQ>\n'
+            '<IMETHODCALL NAME="GetInstance">\n'
+            '<LOCALNAMESPACEPATH>\n'
+            '<NAMESPACE NAME="root"/>\n'
+            '<NAMESPACE NAME="cimv2"/>\n'
+            '</LOCALNAMESPACEPATH>\n'
+            '<IPARAMVALUE NAME="InstanceName">\n'
+            '<INSTANCENAME CLASSNAME="PyWBEM_Person">\n'
+            '<KEYBINDING NAME="Name">\n'
+            '<KEYVALUE VALUETYPE="string">Fritz</KEYVALUE>\n'
+            '</KEYBINDING>\n'
+            '</INSTANCENAME>\n'
+            '</IPARAMVALUE>\n'
+            '<IPARAMVALUE NAME="LocalOnly">\n'
+            '<VALUE>FALSE</VALUE>\n'
+            '</IPARAMVALUE>\n'
+            '</IMETHODCALL>\n'
+            '</SIMPLEREQ>\n'
+            '</MESSAGE>\n'
+            '</CIM>)')
+
+        lc.check(("pywbem.http.test_id", "DEBUG", result))
+
+    @log_capture()
+    def test_stage_http_request_summary(self, lc):
+        """
+        Test http request log record with summary as detail level
+        """
+        self.recorder_setup(detail_level='summary')
+        url, target, method, headers, payload = self.build_http_request()
+        self.test_recorder.stage_http_request('test_id', 11, url, target,
+                                              method, headers, payload)
+
+        result = (
+            "Request:test_id POST /cimom 11 http://blah CIMOperation:"
+            "'MethodCall' "
+            "CIMMethod:'GetInstance' CIMObject:'root/cimv2'\n"
+            '    ')
+
+        lc.check(("pywbem.http.test_id", "DEBUG", result))
+
+    @log_capture()
+    def test_stage_http_request_int(self, lc):
+        """
+        Test http log record with integer as detail_level
+        """
+        self.recorder_setup(detail_level=10)
+
+        url, target, method, headers, payload = self.build_http_request()
+
+        self.test_recorder.stage_http_request('test_id', 11, url, target,
+                                              method, headers, payload)
+
+        result = (
+            "Request:test_id POST /cimom 11 http://blah CIMOperation:"
+            "'MethodCall' "
+            "CIMMethod:'GetInstance' CIMObject:'root/cimv2'\n"
+            '    <?xml vers...')
+
+        lc.check(("pywbem.http.test_id", "DEBUG", result))
+
+    def build_http_response(self):
+        """
+        Build an http response. Builds the complete stage_http_response1
+        and executes and returns the body component so each test can build
+        stage_http_response2 since that is where the logging occurs
+        """
+        body = ('<?xml version="1.0" encoding="utf-8" ?>\n'
+                '<CIM CIMVERSION="2.0" DTDVERSION="2.0">\n'
+                '<MESSAGE ID="1001" PROTOCOLVERSION="1.0">\n'
+                '<SIMPLERSP>\n'
+                '<IMETHODRESPONSE NAME="GetInstance">\n'
+                '<IRETURNVALUE>\n'
+                '<INSTANCE CLASSNAME="PyWBEM_Person">\n'
+                '<PROPERTY NAME="Name" TYPE="string">\n'
+                '<VALUE>Fritz</VALUE>\n'
+                '</PROPERTY>\n'
+                '<PROPERTY NAME="Address" TYPE="string">\n'
+                '<VALUE>Fritz Town</VALUE>\n'
+                '</PROPERTY>\n'
+                '</INSTANCE>\n'
+                '</IRETURNVALUE>\n'
+                '</IMETHODRESPONSE>\n'
+                '</SIMPLERSP>\n'
+                '</MESSAGE>\n'
+                '</CIM>)\n')
+        # body = body.decode('utf-8')
+        headers = OrderedDict([
+            ('Content-type', 'application/xml; charset="utf-8"'),
+            ('Content-length', str(len(body)))])
+        status = 200
+        reason = ""
+        version = 11
+        self.test_recorder.stage_http_response1('test_id', version,
+                                                status, reason, headers)
+
+        return body
+
+    @log_capture()
+    def test_stage_http_response_all(self, lc):
+        """
+        Test http response log record with 'all' detail_level
+        """
+        self.recorder_setup(detail_level='all')
+
+        body = self.build_http_response()
+
+        self.test_recorder.stage_http_response2(body)
+
+        result = ("Response:test_id 200: 11 Content-type:'application/xml; "
+                  'charset="utf-8"\' Content-length:\'450\'\n'
+                  '    <?xml version="1.0" encoding="utf-8" ?>\n'
+                  '<CIM CIMVERSION="2.0" DTDVERSION="2.0">\n'
+                  '<MESSAGE ID="1001" PROTOCOLVERSION="1.0">\n'
+                  '<SIMPLERSP>\n'
+                  '<IMETHODRESPONSE NAME="GetInstance">\n'
+                  '<IRETURNVALUE>\n'
+                  '<INSTANCE CLASSNAME="PyWBEM_Person">\n'
+                  '<PROPERTY NAME="Name" TYPE="string">\n'
+                  '<VALUE>Fritz</VALUE>\n'
+                  '</PROPERTY>\n'
+                  '<PROPERTY NAME="Address" TYPE="string">\n'
+                  '<VALUE>Fritz Town</VALUE>\n'
+                  '</PROPERTY>\n'
+                  '</INSTANCE>\n'
+                  '</IRETURNVALUE>\n'
+                  '</IMETHODRESPONSE>\n'
+                  '</SIMPLERSP>\n'
+                  '</MESSAGE>\n'
+                  '</CIM>)\n')
+
+        lc.check(("pywbem.http.test_id", "DEBUG", result))
+
+    @log_capture()
+    def test_stage_http_response_summary(self, lc):
+        """
+        Test http response log record with 'all' detail_level
+        """
+        self.recorder_setup(detail_level='summary')
+
+        body = self.build_http_response()
+
+        self.test_recorder.stage_http_response2(body)
+
+        result = ("Response:test_id 200: 11 Content-type:'application/xml; "
+                  'charset="utf-8"\' Content-length:\'450\'\n'
+                  '    ')
+
+        lc.check(("pywbem.http.test_id", "DEBUG", result))
+
+    @log_capture()
+    def test_stage_http_response_int(self, lc):
+        """
+        Test http response log record with 'all' detail_level
+        """
+        self.recorder_setup(detail_level=30)
+
+        body = self.build_http_response()
+
+        self.test_recorder.stage_http_response2(body)
+
+        result = ("Response:test_id 200: 11 Content-type:'application/xml; "
+                  'charset="utf-8"\' Content-length:\'450\'\n'
+                  '    <?xml version="1.0" encoding="...')
+
+        lc.check(("pywbem.http.test_id", "DEBUG", result))
+
 
 class LogOperationRecorderTests(BaseLogOperationRecorderTests):
     """