Merge pull request #35 from maykinmedia/issue/34-properly-log-values-…

…for-error-responses

🐛 [#34] Properly log data for error responses

log_outgoing_requests/handlers.py

@@ -92,14 +92,18 @@ def emit(self, record: AnyLogRecord):
             "url": request.url if request else "(unknown)",
             "hostname": parsed_url.netloc if parsed_url else "(unknown)",
             "params": parsed_url.params if parsed_url else "(unknown)",
-            "status_code": response.status_code if response else None,
+            "status_code": response.status_code if response is not None else None,
             "method": request.method if request else "(unknown)",
             "timestamp": timestamp,
-            "response_ms": int(response.elapsed.total_seconds() * 1000)
-            if response
-            else 0,
+            "response_ms": (
+                int(response.elapsed.total_seconds() * 1000)
+                if response is not None
+                else 0
+            ),
             "req_headers": self.format_headers(scrubbed_req_headers),
-            "res_headers": self.format_headers(response.headers if response else {}),
+            "res_headers": self.format_headers(
+                response.headers if response is not None else {}
+            ),
             "trace": "\n".join(format_exception(exception)) if exception else "",
         }
 
@@ -121,7 +125,7 @@ def emit(self, record: AnyLogRecord):
 
             # check response
             if (
-                response
+                response is not None
                 and (
                     processed_response_body := process_body(response, config)
                 ).allow_saving_to_db

log_outgoing_requests/utils.py

@@ -113,9 +113,9 @@ def check_content_type(content_type: str) -> bool:
     For patterns containing a wildcard ("text/*"), check if `content_type.pattern`
     is a substring of any pattern contained in the list.
     """
-    allowed_content_types: Iterable[
-        ContentType
-    ] = settings.LOG_OUTGOING_REQUESTS_CONTENT_TYPES
+    allowed_content_types: Iterable[ContentType] = (
+        settings.LOG_OUTGOING_REQUESTS_CONTENT_TYPES
+    )
     regular_patterns = [
         item.pattern for item in allowed_content_types if not item.pattern.endswith("*")
     ]
@@ -133,9 +133,9 @@ def get_default_encoding(content_type_pattern: str) -> str:
     """
     Get the default encoding for the `ContentType` with the associated pattern.
     """
-    allowed_content_types: Iterable[
-        ContentType
-    ] = settings.LOG_OUTGOING_REQUESTS_CONTENT_TYPES
+    allowed_content_types: Iterable[ContentType] = (
+        settings.LOG_OUTGOING_REQUESTS_CONTENT_TYPES
+    )
 
     regular_types = [
         item for item in allowed_content_types if not item.pattern.endswith("*")

tests/conftest.py

@@ -69,6 +69,25 @@ def request_mock_kwargs():
     }
 
 
+@pytest.fixture
+def request_mock_kwargs_error():
+    return {
+        "url": "http://example.com:8000/some-path-that-doesnt-exist?version=2.0",
+        "status_code": 404,
+        "content": b"404 Not Found",
+        "request_headers": {
+            "Authorization": "test",
+            "Content-Type": "application/json",
+            "Content-Length": "24",
+        },
+        "headers": {
+            "Date": "Tue, 21 Mar 2023 15:24:08 GMT",
+            "Content-Type": "text/plain",
+            "Content-Length": "13",
+        },
+    }
+
+
 @pytest.fixture
 def request_mock_kwargs_binary():
     return {

tests/test_logging.py

@@ -1,6 +1,8 @@
 """Integration tests for the core functionality of the library"""
 
+import datetime
 import logging
+from unittest.mock import patch
 
 import pytest
 import requests
@@ -10,6 +12,11 @@
 from log_outgoing_requests.models import OutgoingRequestsLog
 
 
+def set_elapsed(response, *args, **kwargs):
+    response.elapsed = datetime.timedelta(seconds=2)
+    return response
+
+
 #
 # Local pytest fixtures
 #
@@ -111,6 +118,53 @@ def test_data_is_saved(request_mock_kwargs, request_variants, expected_headers):
         assert request_log.res_body_encoding == "utf-8"
 
 
+@pytest.mark.django_db
+@freeze_time("2021-10-18 13:00:00")
+def test_data_is_saved_for_error_response(
+    request_mock_kwargs_error, request_variants, expected_headers
+):
+    for method, request_func, request_mock in request_variants:
+        request_mock(**request_mock_kwargs_error)
+        with patch(
+            "requests.sessions.default_hooks", return_value={"response": [set_elapsed]}
+        ):
+            response = request_func(
+                request_mock_kwargs_error["url"],
+                headers=request_mock_kwargs_error["request_headers"],
+                json={"test": "request data"},
+            )
+
+        assert response.status_code == 404
+
+        request_log = OutgoingRequestsLog.objects.last()
+
+        assert request_log.method == method
+        assert request_log.status_code == 404
+        assert request_log.hostname == "example.com:8000"
+        assert request_log.params == ""
+        assert request_log.query_params == "version=2.0"
+        assert request_log.response_ms == 2000
+        assert request_log.trace == ""
+        assert str(request_log) == "example.com:8000 at 2021-10-18 13:00:00+00:00"
+        assert (
+            request_log.timestamp.strftime("%Y-%m-%d %H:%M:%S") == "2021-10-18 13:00:00"
+        )
+        # headers
+        assert request_log.req_headers == expected_headers
+        assert (
+            request_log.res_headers == "Date: Tue, 21 Mar 2023 15:24:08 GMT\n"
+            "Content-Type: text/plain\nContent-Length: 13"
+        )
+        # request body
+        assert request_log.req_content_type == "application/json"
+        assert bytes(request_log.req_body) == b'{"test": "request data"}'
+        assert request_log.req_body_encoding == "utf-8"
+        # response body
+        assert request_log.res_content_type == "text/plain"
+        assert bytes(request_log.res_body) == b"404 Not Found"
+        assert request_log.res_body_encoding == "utf-8"
+
+
 #
 # test decoding of binary content
 #