Adding debug logs to base API as urllib3 logs are not helpful for our purpose.

Author: chsou

c8y_api/_base_api.py

@@ -3,6 +3,7 @@
 from __future__ import annotations
 
 import json as json_lib
+import logging
 from typing import Union, Dict, BinaryIO
 
 import collections
@@ -75,6 +76,8 @@ class CumulocityRestApi:
     CONTENT_MANAGED_OBJECT = 'application/vnd.com.nsn.cumulocity.managedobject+json'
     CONTENT_MEASUREMENT_COLLECTION = 'application/vnd.com.nsn.cumulocity.measurementcollection+json'
 
+    log = logging.getLogger(__name__ + '.CumulocityRestApi')
+
     def __init__(self, base_url: str, tenant_id: str, username: str = None, password: str = None,
                  auth: AuthBase = None, application_key: str = None, processing_mode: str = None):
         """Build a CumulocityRestApi instance.
@@ -204,6 +207,8 @@ def get(self, resource: str, params: dict = None, accept: str = None, ordered: b
         """
         additional_headers = self._prepare_headers(accept=accept)
         r = self.session.get(self.base_url + resource, params=params, headers=additional_headers)
+        if self.log.isEnabledFor(logging.DEBUG):
+            self.log.debug(f'GET {resource} {self._format_params(params)} {r.status_code}')
         if r.status_code == 401:
             raise UnauthorizedError(self.METHOD_GET, self.base_url + resource)
         if r.status_code == 403:
@@ -237,6 +242,8 @@ def get_file(self, resource: str, params: dict = None) -> bytes:
                 (only 200 is accepted).
         """
         r = self.session.get(self.base_url + resource, params=params)
+        if self.log.isEnabledFor(logging.DEBUG):
+            self.log.debug(f'GET {resource} {self._format_params(params)} {r.status_code}')
         if r.status_code == 401:
             raise UnauthorizedError(self.METHOD_GET, self.base_url + resource)
         if r.status_code == 403:
@@ -273,6 +280,8 @@ def post(self, resource: str, json: dict, accept: str = None, content_type: str
         assert isinstance(json, dict)
         additional_headers = self._prepare_headers(accept=accept, content_type=content_type)
         r = self.session.post(self.base_url + resource, json=json, headers=additional_headers)
+        if self.log.isEnabledFor(logging.DEBUG):
+            self.log.debug(f"POST {resource} '{json_lib.dumps(json)}' {r.status_code}")
         if r.status_code == 401:
             raise UnauthorizedError(self.METHOD_POST, self.base_url + resource, message=r.json()['message'])
         if r.status_code == 403:
@@ -324,6 +333,9 @@ def perform_post(open_file):
         else:
             r = perform_post(file)
 
+        if self.log.isEnabledFor(logging.DEBUG):
+            self.log.debug(f"POST {resource} '{file}' {self._format_params(object)} {r.status_code}")
+
         if r.status_code == 401:
             raise UnauthorizedError(self.METHOD_POST, self.base_url + resource)
         if r.status_code == 403:
@@ -362,6 +374,8 @@ def put(self, resource: str, json: dict, params: dict = None,
         assert isinstance(json, dict)
         additional_headers = self._prepare_headers(accept=accept, content_type=content_type)
         r = self.session.put(self.base_url + resource, json=json, params=params, headers=additional_headers)
+        if self.log.isEnabledFor(logging.DEBUG):
+            self.log.debug(f"PUT {resource} {self._format_params(params)} '{json_lib.dumps(json)}' {r.status_code}")
         if r.status_code == 401:
             raise UnauthorizedError(self.METHOD_PUT, self.base_url + resource)
         if r.status_code == 403:
@@ -413,6 +427,8 @@ def read_file_data(f):
         additional_headers = self._prepare_headers(accept=accept, content_type=content_type)
         data = read_file_data(file)
         r = self.session.put(self.base_url + resource, data=data, headers=additional_headers)
+        if self.log.isEnabledFor(logging.DEBUG):
+            self.log.debug(f"PUT {resource} '{file}' {r.status_code}")
         if r.status_code == 401:
             raise UnauthorizedError(self.METHOD_PUT, self.base_url + resource)
         if r.status_code == 403:
@@ -448,6 +464,8 @@ def delete(self, resource: str, json: dict = None, params: dict = None):
         if json:
             assert isinstance(json, dict)
         r = self.session.delete(self.base_url + resource, json=json, params=params, headers={'Accept': None})
+        if self.log.isEnabledFor(logging.DEBUG):
+            self.log.debug(f"DELETE {resource} {self._format_params(params)} '{json_lib.dumps(json)}' {r.status_code}")
         if r.status_code == 401:
             raise UnauthorizedError(self.METHOD_DELETE, self.base_url + resource)
         if r.status_code == 403:
@@ -496,6 +514,14 @@ def format_value(value):
 
         return {cls._format_header_key(key): format_value(value) for key, value in kwargs.items() if value is not None}
 
+    @staticmethod
+    def _format_params(params):
+        if not params:
+            return '-'
+        return ', '.join(
+            [f"{k}={v}" for k, v in params.items()]
+        )
+
     @staticmethod
     def _format_header_key(key: str) -> str:
         """Format a snake_case argument name into a proper Header-Name.

tests/test_base_api.py

@@ -4,7 +4,7 @@
 
 import base64
 from typing import Type
-from unittest.mock import patch, Mock
+from unittest.mock import patch, Mock, PropertyMock
 
 import json
 import pytest
@@ -18,6 +18,7 @@
     AccessDeniedError,
     HttpError
 )
+from tests.utils import isolate_last_call_arg, assert_all_in_any, assert_all_not_in_any
 
 
 @pytest.fixture(scope='function')
@@ -351,3 +352,70 @@ def test_empty_response(mock_c8y: CumulocityRestApi):
                  url=mock_c8y.base_url + '/resource',
                  status=200)
         mock_c8y.put('/resource', json={})
+
+
+@pytest.mark.parametrize(
+    'method, kwargs, expected, not_expected',
+    [
+        ('get', {"params": {"a": 1}}, ['a=1'], ['{']),
+        ('post', {"json": {"b": 2}}, ['{"b": 2}'], []),
+        ('put', {"params": {"a": 1}, "json": {"b": 2}}, ['a=1', '{"b": 2}'], []),
+        ('delete', {"params": {"a": 1}, "json": {"b": 2}}, ['a=1', '{"b": 2}'], []),
+    ],
+    ids=[
+        "get",
+        "post",
+        "put",
+        "delete",
+    ]
+)
+@patch('c8y_api.CumulocityRestApi.session', new_callable=PropertyMock)
+def test_request_logging_simple(session_property_mock, mock_c8y: CumulocityRestApi,
+                                method, kwargs, expected, not_expected):
+    """Verify that requests are logged properly."""
+
+    session_mock = Mock(name='my-session-mock')
+    getattr(session_mock, method).return_value = Mock(status_code=200)
+    session_property_mock.return_value = session_mock
+    mock_c8y.log = Mock(isEnabledFor=Mock(return_value=True))
+
+    getattr(mock_c8y, method)('/resource', **kwargs)
+    mock_c8y.log.debug.assert_called_once()
+    msg = isolate_last_call_arg(mock_c8y.log.debug, 0)
+    assert_all_in_any([method.upper(), '/resource', *expected], msg)
+    assert_all_not_in_any(not_expected, msg)
+
+
+@patch('c8y_api.CumulocityRestApi.session', new_callable=PropertyMock)
+def test_request_logging_file(session_property_mock, mock_c8y: CumulocityRestApi, ):
+    """Verify that requests are logged properly."""
+
+    session_mock = Mock(name='my-session-mock')
+    session_property_mock.return_value = session_mock
+    mock_c8y.log = Mock(isEnabledFor=Mock(return_value=True))
+
+    # GET File
+    session_mock.get.return_value = Mock(status_code=200)
+    mock_c8y.log.debug.reset_mock()
+    mock_c8y.get_file('/resource', params={'a': 1})
+    mock_c8y.log.debug.assert_called_once()
+    msg = isolate_last_call_arg(mock_c8y.log.debug, 0)
+    assert_all_in_any(['/resource', 'GET', 'a=1'], msg)
+
+    # POST File
+    mock_c8y.log.debug.reset_mock()
+    session_mock.post.return_value = Mock(status_code=201)  # posting file should give 201
+    with patch("builtins.open"):
+        mock_c8y.post_file('/resource', file='filename', object={'a': 1})
+    mock_c8y.log.debug.assert_called_once()
+    msg = isolate_last_call_arg(mock_c8y.log.debug, 0)
+    assert_all_in_any(['/resource', 'POST', 'a=1', 'filename'], msg)
+
+    # PUT File
+    mock_c8y.log.debug.reset_mock()
+    session_mock.put.return_value = Mock(status_code=201)  # putting file should give 201
+    with patch("builtins.open"):
+        mock_c8y.put_file('/resource', file='filename')
+    mock_c8y.log.debug.assert_called_once()
+    msg = isolate_last_call_arg(mock_c8y.log.debug, 0)
+    assert_all_in_any(['/resource', 'PUT', 'filename'], msg)