#28: Add session history to ease request debugging

README.rst

@@ -273,6 +273,42 @@ Deleting resources
     cust1.commit() # Actually delete
 
 
+Session history for debugging
+------------------
+
+.. code-block:: python
+
+    # You can use session history to debug http requests.
+    # Session history will be enabled, if you set the log level to DEBUG
+    # or explicitly set a session parameter enable_history_at_log level to a log level
+    # equal or lower than the actual log level.
+
+    # Session history will be enabled by: (Python log level is WARNING by default)
+    s = Session('http://localhost:8080/', schema=models_as_jsonschema,
+                enable_history_at_loglevel='WARNING')
+    # or
+    import logging
+    logging.basicConfig(level='DEBUG')
+    s = Session('http://localhost:8080/', schema=models_as_jsonschema)
+
+    # Session history will be disabled
+    logging.basicConfig(level='INFO')
+    s = Session('http://localhost:8080/', schema=models_as_jsonschema)
+
+    # Session history is a list of session history items.
+    # You can see the information about the request and response
+    # For example
+    s.history.latest
+    # will print out some data about the latest request
+    # That actually equals to
+    s.history[-1]
+
+    # You can see the latest server response by
+    print(s.history.latest.response_content)
+    # or to see the response headers
+    s.history.latest.headers
+
+
 Credits
 =======
 

src/jsonapi_client/session.py

@@ -56,6 +56,78 @@
 NOT_FOUND = object()
 
 
+class SessionHistory(list):
+    @property
+    def latest(self):
+        if len(self):
+            return self[-1]
+        else:
+            return None
+
+
+class SessionHistoryItem:
+    def __init__(self, session: 'Session', url: str, http_method: str, response, send_json: dict=None):
+        self.session = session
+        self.response = response
+        self.url = url
+        self.send_json = send_json
+        self.http_method = http_method.upper()
+
+    def __repr__(self):
+        content = self.content
+        content_cut_after = 100
+        if len(content) > content_cut_after:
+            content = f"{content[:content_cut_after]}..."
+        request_str = f"Request: {self.url}\n  method: {self.http_method}\n"
+        if self.send_json:
+            request_content = json.dumps(self.send_json)
+            if len(request_content) > content_cut_after:
+                request_content = f"{request_content[:content_cut_after]}..."
+            request_str += f"  payload: {request_content}\n"
+        r =  f"{request_str}" \
+             f"Response: \n  status code: {self.status_code}\n" \
+               f"  content length: {self.content_length}\n" \
+               f"  content: {content}"
+        return r
+
+    @property
+    def content(self):
+        if self.session.enable_async:
+            return self.response._body
+        else:
+            return self.response.content
+
+    @property
+    def response_content(self):
+        """
+        This is used to pretty print the contents for debugging purposes.
+        If you don't want pretty print, please use self.response.content directly
+        Example: If session is s, you can pretty print out the latest content by
+        print(s.history.latest.content)
+        """
+        loaded = json.loads(self.response.content)
+        return json.dumps(loaded, indent=4, sort_keys=True)
+
+    @property
+    def payload(self):
+        return json.dumps(self.send_json, indent=4, sort_keys=True)
+
+    @property
+    def content_length(self):
+        return len(self.content)
+
+    @property
+    def headers(self):
+        return self.response.headers
+
+    @property
+    def status_code(self):
+        if self.session.enable_async:
+            return self.response.status
+        else:
+            return self.response.status_code
+
+
 class Schema:
     """
     Container for model schemas with associated methods.
@@ -123,7 +195,8 @@ def __init__(self, server_url: str=None,
                  schema: dict=None,
                  request_kwargs: dict=None,
                  loop: 'AbstractEventLoop'=None,
-                 use_relationship_iterator: bool=False,) -> None:
+                 use_relationship_iterator: bool=False,
+                 enable_history_at_loglevel: str='DEBUG') -> None:
         self._server: ParseResult
         self.enable_async = enable_async
 
@@ -143,6 +216,8 @@ def __init__(self, server_url: str=None,
             import aiohttp
             self._aiohttp_session = aiohttp.ClientSession(loop=loop)
         self.use_relationship_iterator = use_relationship_iterator
+        self._enable_history = logger.isEnabledFor(getattr(logging, enable_history_at_loglevel))
+        self.history = SessionHistory()
 
     def add_resources(self, *resources: 'ResourceObject') -> None:
         """
@@ -475,6 +550,13 @@ async def _ext_fetch_by_url_async(self, url: str) -> 'Document':
         json_data = await self._fetch_json_async(url)
         return self.read(json_data, url)
 
+    def _append_to_session_history(self, url: str, http_method: str,
+                                   response, send_json: dict=None):
+        if self._enable_history:
+            self.history.append(
+                SessionHistoryItem(self, url, http_method, response, send_json)
+            )
+
     def _fetch_json(self, url: str) -> dict:
         """
         Internal use.
@@ -487,6 +569,7 @@ def _fetch_json(self, url: str) -> dict:
         logger.info('Fetching document from url %s', parsed_url)
         response = requests.get(parsed_url.geturl(), **self._request_kwargs)
         response_content = response.json()
+        self._append_to_session_history(url, 'GET', response)
         if response.status_code == HttpStatus.OK_200:
             return response_content
         else:
@@ -508,6 +591,7 @@ async def _fetch_json_async(self, url: str) -> dict:
         async with self._aiohttp_session.get(parsed_url.geturl(),
                                              **self._request_kwargs) as response:
             response_content = await response.json(content_type='application/vnd.api+json')
+            self._append_to_session_history(url, 'GET', response)
             if response.status == HttpStatus.OK_200:
                 return response_content
             else:
@@ -536,6 +620,7 @@ def http_request(self, http_method: str, url: str, send_json: dict,
                                     **kwargs)
 
         response_json = response.json()
+        self._append_to_session_history(url, http_method, response, send_json)
         if response.status_code not in expected_statuses:
             raise DocumentError(f'Could not {http_method.upper()} '
                                 f'({response.status_code}): '
@@ -574,6 +659,7 @@ async def http_request_async(
                 **kwargs) as response:
 
             response_json = await response.json(content_type=content_type)
+            self._append_to_session_history(url, http_method, response, send_json)
             if response.status not in expected_statuses:
                 raise DocumentError(f'Could not {http_method.upper()} '
                                     f'({response.status}): '

tests/test_client.py

@@ -1762,3 +1762,169 @@ async def test_error_handling_posting_async(loop, session):
 
     assert str(exp.value) == 'Could not POST (500): Internal server error'
     patcher.stop()
+
+
+def test_history_get():
+    response = Response()
+    response.url = URL('http://localhost:8080/leases')
+    response.request = mock.Mock()
+    response.headers = {'Content-Type': 'application/vnd.api+json'}
+    response._content = json.dumps({'data': []}).encode('UTF-8')
+    response.status_code = 200
+
+    patcher = mock.patch('requests.get')
+    client_mock = patcher.start()
+    # Session history will be disabled, if not explicitly enabled
+    # or log level set to DEBUG.
+    # Python loglevel is WARNING by default.
+    s = Session(
+        'http://localhost:8080',
+        schema=api_schema_all,
+    )
+    client_mock.return_value = response
+    s.get('leases')
+    assert len(s.history) == 0
+
+    s = Session(
+        'http://localhost:8080',
+        schema=api_schema_all,
+        enable_history_at_loglevel='WARNING'
+    )
+    s.get('leases')
+    assert len(s.history) == 1
+    assert s.history.latest == s.history[-1]
+    latest = s.history.latest
+    assert latest.url == 'http://localhost:8080/leases'
+    assert latest.http_method == 'GET'
+    assert latest.send_json is None
+    assert latest.content_length == len(response._content)
+    assert latest.status_code == 200
+
+
+def test_history_post():
+    response = Response()
+    response.url = URL('http://localhost:8080/invalid')
+    response.request = mock.Mock()
+    response.headers = {'Content-Type': 'application/vnd.api+json'}
+    response._content = json.dumps(
+        {'errors': [{'title': 'Internal server error'}]}
+    ).encode('UTF-8')
+    response.status_code = 500
+
+    patcher = mock.patch('requests.request')
+    client_mock = patcher.start()
+    s = Session('http://localhost:8080', schema=leases, enable_history_at_loglevel='WARNING')
+    client_mock.return_value = response
+    a = s.create('leases')
+    assert a.is_dirty
+    a.lease_id = '1'
+    a.active_status = 'pending'
+    a.reference_number = 'test'
+    with pytest.raises(DocumentError):
+        a.commit()
+
+    assert len(s.history) == 1
+    latest = s.history.latest
+    assert latest.url == 'http://localhost:8080/leases'
+    assert latest.http_method == 'POST'
+    assert latest.send_json == {
+        'data': {
+            'attributes': {
+                'active-status': 'pending',
+                'lease-id': '1',
+                'reference-number': 'test'
+            },
+            'relationships': {},
+            'type': 'leases'
+        }
+    }
+    assert latest.content_length == len(response._content)
+    assert latest.status_code == 500
+
+
+@pytest.mark.asyncio
+async def test_history_async_get(loop, session):
+    response = ClientResponse('get', URL('http://localhost/invalid'),
+                              request_info=mock.Mock(),
+                              writer=mock.Mock(),
+                              continue100=None,
+                              timer=TimerNoop(),
+                              traces=[],
+                              loop=loop,
+                              session=session,
+                              )
+    response._headers = {'Content-Type': 'application/vnd.api+json'}
+    response._body = json.dumps({'errors': [{'title': 'Resource not found'}]}).encode('UTF-8')
+    response.status = 404
+
+    patcher = mock.patch('aiohttp.ClientSession')
+    client_mock = patcher.start()
+    s = Session(
+        'http://localhost', schema=leases, enable_async=True, enable_history_at_loglevel='WARNING'
+    )
+    client_mock().get.return_value = response
+    with pytest.raises(DocumentError):
+        await s.get('invalid')
+
+    patcher.stop()
+
+    assert len(s.history) == 1
+    latest = s.history.latest
+    assert latest.url == 'http://localhost/invalid'
+    assert latest.http_method == 'GET'
+    assert latest.send_json is None
+    assert latest.content_length == len(response._body)
+    assert latest.status_code == 404
+
+
+@pytest.mark.asyncio
+async def test_history_async_post(loop, session):
+    response = ClientResponse('post', URL('http://localhost:8080/leases'),
+                              request_info=mock.Mock(),
+                              writer=mock.Mock(),
+                              continue100=None,
+                              timer=TimerNoop(),
+                              traces=[],
+                              loop=loop,
+                              session=session,
+                              )
+    response._headers = {'Content-Type': 'application/vnd.api+json'}
+    response._body = json.dumps({'errors': [{'title': 'Internal server error'}]}).encode('UTF-8')
+    response.status = 500
+
+    patcher = mock.patch('aiohttp.ClientSession.request')
+    request_mock = patcher.start()
+    s = Session(
+        'http://localhost:8080',
+        schema=api_schema_all,
+        enable_async=True,
+        enable_history_at_loglevel='WARNING'
+    )
+    request_mock.return_value = response
+    s.create('leases')
+    a = s.create('leases')
+    assert a.is_dirty
+    a.lease_id = '1'
+    a.active_status = 'pending'
+    a.reference_number = 'test'
+    with pytest.raises(DocumentError):
+        await a.commit()
+    patcher.stop()
+
+    assert len(s.history) == 1
+    latest = s.history.latest
+    assert latest.url == 'http://localhost:8080/leases'
+    assert latest.http_method == 'POST'
+    assert latest.send_json == {
+        'data': {
+            'attributes': {
+                'active-status': 'pending',
+                'lease-id': '1',
+                'reference-number': 'test'
+            },
+            'relationships': {},
+            'type': 'leases'
+        }
+    }
+    assert latest.content_length == len(response._body)
+    assert latest.status_code == 500