Merge pull request #539 from maykinmedia/fix/1249-add-headers-to-outg…

…oing-requests-logging

[#1249] Add headers to outgoing requests logging

src/log_outgoing_requests/admin.py

@@ -17,6 +17,8 @@ class OutgoingRequestsLogAdmin(admin.ModelAdmin):
         "timestamp",
         "req_content_type",
         "res_content_type",
+        "req_headers",
+        "res_headers",
         "trace",
     )
     readonly_fields = fields
@@ -30,7 +32,7 @@ class OutgoingRequestsLogAdmin(admin.ModelAdmin):
         "timestamp",
     )
     list_filter = ("method", "status_code", "hostname")
-    search_fields = ("params", "query_params", "hostname")
+    search_fields = ("url", "params", "hostname")
     date_hierarchy = "timestamp"
     show_full_result_count = False
 

src/log_outgoing_requests/formatters.py

@@ -3,21 +3,28 @@
 
 
 class HttpFormatter(logging.Formatter):
+    def _formatHeaders(self, d):
+        return "\n".join(f"{k}: {v}" for k, v in d.items())
+
     def formatMessage(self, record):
         result = super().formatMessage(record)
         if record.name == "requests":
             result += textwrap.dedent(
                 """
                 ---------------- request ----------------
                 {req.method} {req.url}
+                {reqhdrs}
 
                 ---------------- response ----------------
                 {res.status_code} {res.reason} {res.url}
+                {reshdrs}
                 
             """
             ).format(
                 req=record.req,
                 res=record.res,
+                reqhdrs=self._formatHeaders(record.req.headers),
+                reshdrs=self._formatHeaders(record.res.headers),
             )
 
         return result

src/log_outgoing_requests/handlers.py

@@ -14,11 +14,15 @@ def emit(self, record):
 
             # save only the requests coming from the library requests
             if record and record.getMessage() == "Outgoing request":
+                safe_req_headers = record.req.headers.copy()
+
+                if "Authorization" in safe_req_headers:
+                    safe_req_headers["Authorization"] = "***hidden***"
+
                 if record.exc_info:
                     trace = traceback.format_exc()
 
                 parsed_url = urlparse(record.req.url)
-
                 kwargs = {
                     "url": record.req.url,
                     "hostname": parsed_url.hostname,
@@ -29,7 +33,12 @@ def emit(self, record):
                     "res_content_type": record.res.headers.get("Content-Type", ""),
                     "timestamp": record.requested_at,
                     "response_ms": int(record.res.elapsed.total_seconds() * 1000),
+                    "req_headers": self.format_headers(safe_req_headers),
+                    "res_headers": self.format_headers(record.res.headers),
                     "trace": trace,
                 }
 
                 OutgoingRequestsLog.objects.create(**kwargs)
+
+    def format_headers(self, headers):
+        return "\n".join(f"{k}: {v}" for k, v in headers.items())

src/log_outgoing_requests/log_requests.py

@@ -30,7 +30,7 @@ def install_outgoing_requests_logging():
     Session._original_request = Session.request
 
     def new_request(self, *args, **kwargs):
-        kwargs.setdefault("hooks", {"response": hook_requests_logging})
+        self.hooks["response"].append(hook_requests_logging)
         return self._original_request(*args, **kwargs)
 
     Session.request = new_request

src/log_outgoing_requests/migrations/0003_auto_20230321_0724.py

@@ -0,0 +1,33 @@
+# Generated by Django 3.2.15 on 2023-03-21 06:24
+
+from django.db import migrations, models
+
+
+class Migration(migrations.Migration):
+
+    dependencies = [
+        ("log_outgoing_requests", "0002_alter_outgoingrequestslog_url"),
+    ]
+
+    operations = [
+        migrations.AddField(
+            model_name="outgoingrequestslog",
+            name="req_headers",
+            field=models.TextField(
+                blank=True,
+                help_text="The request headers.",
+                null=True,
+                verbose_name="Request headers",
+            ),
+        ),
+        migrations.AddField(
+            model_name="outgoingrequestslog",
+            name="res_headers",
+            field=models.TextField(
+                blank=True,
+                help_text="The response headers.",
+                null=True,
+                verbose_name="Response headers",
+            ),
+        ),
+    ]

src/log_outgoing_requests/models.py

@@ -13,6 +13,8 @@ class OutgoingRequestsLog(models.Model):
         default="",
         help_text=_("The url of the outgoing request."),
     )
+
+    # hostname is added so we can filter on it in the admin page
     hostname = models.CharField(
         verbose_name=_("Hostname"),
         max_length=255,
@@ -52,6 +54,18 @@ class OutgoingRequestsLog(models.Model):
         blank=True,
         help_text=_("The content type of the response."),
     )
+    req_headers = models.TextField(
+        verbose_name=_("Request headers"),
+        blank=True,
+        null=True,
+        help_text=_("The request headers."),
+    )
+    res_headers = models.TextField(
+        verbose_name=_("Response headers"),
+        blank=True,
+        null=True,
+        help_text=_("The response headers."),
+    )
     response_ms = models.PositiveIntegerField(
         verbose_name=_("Response in ms"),
         default=0,
@@ -79,6 +93,9 @@ def __str__(self):
         )
 
     @cached_property
+    def url_parsed(self):
+        return urlparse(self.url)
+
+    @property
     def query_params(self):
-        parsed_url = urlparse(self.url)
-        return parsed_url.query
+        return self.url_parsed.query

src/log_outgoing_requests/tests/test_logging.py

@@ -17,6 +17,7 @@ def _setUpMocks(self, m):
             content=b"some content",
         )
 
+    @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True)
     def test_outgoing_requests_are_logged(self, m):
         self._setUpMocks(m)
 
@@ -30,9 +31,8 @@ def test_outgoing_requests_are_logged(self, m):
 
     @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True)
     def test_expected_data_is_saved_when_saving_enabled(self, m):
-        self._setUpMocks(m)
-
         methods = [
+            ("GET", requests.get, m.get),
             ("POST", requests.post, m.post),
             ("PUT", requests.put, m.put),
             ("PATCH", requests.patch, m.patch),
@@ -45,10 +45,31 @@ def test_expected_data_is_saved_when_saving_enabled(self, m):
                 mocked(
                     "http://example.com/some-path?version=2.0",
                     status_code=200,
-                    content=b"some content",
+                    json={"test": "data"},
+                    request_headers={
+                        "Authorization": "test",
+                        "Content-Type": "text/html",
+                    },
+                    headers={
+                        "Date": "Tue, 21 Mar 2023 15:24:08 GMT",
+                        "Content-Type": "application/json",
+                    },
+                )
+                expected_req_headers = (
+                    "User-Agent: python-requests/2.26.0\n"
+                    "Accept-Encoding: gzip, deflate, br\n"
+                    "Accept: */*\n"
+                    "Connection: keep-alive\n"
+                    "Authorization: ***hidden***\n"
+                    "Content-Type: text/html"
                 )
+                if method not in ["HEAD", "GET"]:
+                    expected_req_headers += "\nContent-Length: 0"
 
-                response = func("http://example.com/some-path?version=2.0")
+                response = func(
+                    "http://example.com/some-path?version=2.0",
+                    headers={"Authorization": "test", "Content-Type": "text/html"},
+                )
 
                 request_log = OutgoingRequestsLog.objects.last()
 
@@ -60,15 +81,33 @@ def test_expected_data_is_saved_when_saving_enabled(self, m):
                 self.assertEqual(request_log.query_params, "version=2.0")
                 self.assertEqual(response.status_code, 200)
                 self.assertEqual(request_log.method, method)
-                self.assertEqual(request_log.req_content_type, "")
-                self.assertEqual(request_log.res_content_type, "")
+                self.assertEqual(request_log.req_content_type, "text/html")
+                self.assertEqual(request_log.res_content_type, "application/json")
                 self.assertEqual(request_log.response_ms, 0)
+                self.assertEqual(request_log.req_headers, expected_req_headers)
+                self.assertEqual(
+                    request_log.res_headers,
+                    "Date: Tue, 21 Mar 2023 15:24:08 GMT\nContent-Type: application/json",
+                )
                 self.assertEqual(
                     request_log.timestamp.strftime("%Y-%m-%d %H:%M:%S"),
                     "2021-10-18 13:00:00",
                 )
                 self.assertIsNone(request_log.trace)
 
+    @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True)
+    def test_authorization_header_is_hidden(self, m):
+        self._setUpMocks(m)
+
+        requests.get(
+            "http://example.com/some-path?version=2.0",
+            headers={"Authorization": "test"},
+        )
+        log = OutgoingRequestsLog.objects.get()
+
+        self.assertIn("Authorization: ***hidden***", log.req_headers)
+
+    @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=False)
     def test_data_is_not_saved_when_saving_disabled(self, m):
         self._setUpMocks(m)