Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[#1185] Outgoing requests tracking #524

Merged
merged 4 commits into from
Mar 15, 2023
Merged

[#1185] Outgoing requests tracking #524

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
246aa80
[#1185] Started with tracking external api calls
vaszig Mar 8, 2023
f9d8bb7
[#1185] Refactored logging approach and split off app
vaszig Mar 14, 2023
9b0da29
[#1185] Added requests logging to the general settings logging dict
vaszig Mar 14, 2023
20eaf77
[#1185] Changes according to PR review
vaszig Mar 15, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
31 changes: 27 additions & 4 deletions src/log_outgoing_requests/admin.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,23 +1,46 @@
from django.contrib import admin
from django.utils.translation import gettext as _

from .models import OutgoingRequestsLog


@admin.register(OutgoingRequestsLog)
vaszig marked this conversation as resolved.
Show resolved Hide resolved
class OutgoingRequestsLogAdmin(admin.ModelAdmin):
fields = (
"url",
"hostname",
"path",
"params",
"query_params",
"params",
"status_code",
"method",
"response_ms",
"timestamp",
"req_content_type",
"res_content_type",
"trace",
)
readonly_fields = fields
list_display = fields
list_display = (
"hostname",
"query_params",
"params",
"status_code",
"method",
"response_ms",
"timestamp",
)
list_filter = ("method", "status_code", "hostname")
search_fields = ("path",)
search_fields = ("params", "query_params", "hostname")
date_hierarchy = "timestamp"
show_full_result_count = False

def has_add_permission(self, request):
return False

def has_change_permission(self, request, obj=None):
return False

def query_params(self, obj):
return obj.query_params

query_params.short_description = _("Query parameters")
8 changes: 0 additions & 8 deletions src/log_outgoing_requests/formatters.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,29 +3,21 @@


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}

{req.body}
---------------- 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
12 changes: 5 additions & 7 deletions src/log_outgoing_requests/handlers.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,28 +7,26 @@

class DatabaseOutgoingRequestsHandler(logging.Handler):
def emit(self, record):
if (
settings.LOG_OUTGOING_REQUESTS_ENABLED
and settings.LOG_OUTGOING_REQUESTS_DB_SAVE
):
if settings.LOG_OUTGOING_REQUESTS_DB_SAVE:
from .models import OutgoingRequestsLog

trace = None

# save only the requests coming from the library requests
if record and record.getMessage() == "External request":
if record and record.getMessage() == "Outgoing request":
if record.exc_info:
trace = traceback.format_exc()

parsed_url = urlparse(record.req.url)

kwargs = {
vaszig marked this conversation as resolved.
Show resolved Hide resolved
"url": record.req.url,
"hostname": parsed_url.hostname,
"path": parsed_url.path,
"params": parsed_url.params,
"query_params": parsed_url.query,
"status_code": record.res.status_code,
"method": record.req.method,
"req_content_type": record.req.headers.get("Content-Type", ""),
"res_content_type": record.res.headers.get("Content-Type", ""),
"timestamp": record.requested_at,
"response_ms": int(record.res.elapsed.total_seconds() * 1000),
"trace": trace,
Expand Down
4 changes: 2 additions & 2 deletions src/log_outgoing_requests/log_requests.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,12 +13,12 @@ def hook_requests_logging(response, *args, **kwargs):
A hook for requests library in order to add extra data to the logs
"""
extra = {"requested_at": timezone.now(), "req": response.request, "res": response}
logger.debug("External request", extra=extra)
logger.debug("Outgoing request", extra=extra)


def install_outgoing_requests_logging():
"""
Log all external requests which are made by the library requests during a session.
Log all outgoing requests which are made by the library requests during a session.
"""

if hasattr(Session, "_original_request"):
Expand Down
47 changes: 30 additions & 17 deletions src/log_outgoing_requests/migrations/0001_initial.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
# Generated by Django 3.2.15 on 2023-03-14 09:11
# Generated by Django 3.2.15 on 2023-03-15 06:41

from django.db import migrations, models

Expand All @@ -23,23 +23,22 @@ class Migration(migrations.Migration):
),
),
(
"hostname",
models.CharField(
"url",
models.URLField(
blank=True,
default="",
help_text="The hostname part of the url.",
max_length=255,
verbose_name="Hostname",
help_text="The url of the outgoing request.",
verbose_name="URL",
),
),
(
"path",
"hostname",
models.CharField(
blank=True,
default="",
help_text="The path part of the url.",
help_text="The hostname part of the url.",
max_length=255,
verbose_name="Path",
verbose_name="Hostname",
),
),
(
Expand All @@ -50,20 +49,13 @@ class Migration(migrations.Migration):
verbose_name="Parameters",
),
),
(
"query_params",
models.TextField(
blank=True,
help_text="The query parameters part of the url (if they exist).",
verbose_name="Query parameters",
),
),
(
"status_code",
models.PositiveIntegerField(
blank=True,
help_text="The status code of the response.",
null=True,
verbose_name="Status code",
),
),
(
Expand All @@ -73,6 +65,27 @@ class Migration(migrations.Migration):
default="",
help_text="The type of request method.",
max_length=10,
verbose_name="Method",
),
),
(
"req_content_type",
models.CharField(
blank=True,
default="",
help_text="The content type of the request.",
max_length=50,
verbose_name="Request content type",
),
),
(
"res_content_type",
models.CharField(
blank=True,
default="",
help_text="The content type of the response.",
max_length=50,
verbose_name="Response content type",
),
),
(
Expand Down
46 changes: 33 additions & 13 deletions src/log_outgoing_requests/models.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,41 +1,56 @@
from urllib.parse import urlparse

from django.db import models
from django.utils.functional import cached_property
from django.utils.translation import gettext_lazy as _


class OutgoingRequestsLog(models.Model):
url = models.URLField(
verbose_name=_("URL"),
blank=True,
default="",
help_text=_("The url of the outgoing request."),
)
hostname = models.CharField(
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd put a comment here to note that .hostname is obviously part of .url but we also have it as a field so we can filter on it in the admin.

verbose_name=_("Hostname"),
max_length=255,
default="",
blank=True,
help_text=_("The hostname part of the url."),
)
path = models.CharField(
verbose_name=_("Path"),
max_length=255,
default="",
blank=True,
help_text=_("The path part of the url."),
)
params = models.TextField(
verbose_name=_("Parameters"),
blank=True,
help_text=_("The parameters (if they exist)."),
)
query_params = models.TextField(
verbose_name=_("Query parameters"),
blank=True,
help_text=_("The query parameters part of the url (if they exist)."),
)
status_code = models.PositiveIntegerField(
null=True, blank=True, help_text=_("The status code of the response.")
verbose_name=_("Status code"),
null=True,
blank=True,
help_text=_("The status code of the response."),
)
method = models.CharField(
verbose_name=_("Method"),
max_length=10,
default="",
blank=True,
help_text=_("The type of request method."),
)
req_content_type = models.CharField(
verbose_name=_("Request content type"),
max_length=50,
default="",
blank=True,
help_text=_("The content type of the request."),
)
res_content_type = models.CharField(
verbose_name=_("Response content type"),
max_length=50,
default="",
blank=True,
help_text=_("The content type of the response."),
)
response_ms = models.PositiveIntegerField(
verbose_name=_("Response in ms"),
default=0,
Expand All @@ -61,3 +76,8 @@ def __str__(self):
return ("{hostname} at {date}").format(
hostname=self.hostname, date=self.timestamp
)

@cached_property
def query_params(self):
parsed_url = urlparse(self.url)
return parsed_url.query
Comment on lines +80 to +83
Copy link
Contributor

@Bartvaderkin Bartvaderkin Mar 15, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is ok for now since we only take the query, but if we'd want more url components you'd cache the urlparse() result and access parts of it like so:

@cached_property
def url_parsed(self):
    return urlparse(self.url)

@property
def query_params(self):
    return self.url_parsed.query

@property
def scheme(self):
    return self.url_parsed.scheme

43 changes: 18 additions & 25 deletions src/log_outgoing_requests/tests/test_logging.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,3 @@
from unittest.mock import patch

from django.test import TestCase, override_settings

import requests
Expand All @@ -19,24 +17,19 @@ def _setUpMocks(self, m):
content=b"some content",
)

@override_settings(
LOG_OUTGOING_REQUESTS_ENABLED=True, LOG_OUTGOING_REQUESTS_DB_SAVE=True
)
def test_external_requests_are_logged_when_tracking_and_save_enabled(self, m):
def test_outgoing_requests_are_logged(self, m):
self._setUpMocks(m)

with self.assertLogs("requests", level="DEBUG") as logs:
requests.get("http://example.com/some-path?version=2.0")

self.assertEqual(logs.output, ["DEBUG:requests:External request"])
self.assertEqual(logs.output, ["DEBUG:requests:Outgoing request"])
self.assertEqual(logs.records[0].name, "requests")
self.assertEqual(logs.records[0].getMessage(), "External request")
self.assertEqual(logs.records[0].getMessage(), "Outgoing request")
self.assertEqual(logs.records[0].levelname, "DEBUG")

@override_settings(
LOG_OUTGOING_REQUESTS_ENABLED=True, LOG_OUTGOING_REQUESTS_DB_SAVE=True
)
def test_expected_data_is_saved_when_tracking_and_save_enabled(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 = [
Expand All @@ -59,48 +52,48 @@ def test_expected_data_is_saved_when_tracking_and_save_enabled(self, m):

request_log = OutgoingRequestsLog.objects.last()

self.assertEqual(
request_log.url, "http://example.com/some-path?version=2.0"
)
self.assertEqual(request_log.hostname, "example.com")
self.assertEqual(request_log.path, "/some-path")
self.assertEqual(request_log.params, "")
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.response_ms, 0)
self.assertEqual(
request_log.timestamp.strftime("%Y-%m-%d %H:%M:%S"),
"2021-10-18 13:00:00",
)
self.assertIsNone(request_log.trace)

def test_data_is_not_saved_when_tracking_and_save_disabled(self, m):
def test_data_is_not_saved_when_saving_disabled(self, m):
self._setUpMocks(m)

with self.assertLogs("requests", level="DEBUG") as logs:
requests.get("http://example.com/some-path?version=2.0")

self.assertEqual(logs.output, ["DEBUG:requests:External request"])
self.assertEqual(logs.output, ["DEBUG:requests:Outgoing request"])
self.assertEqual(logs.records[0].name, "requests")
self.assertEqual(logs.records[0].getMessage(), "External request")
self.assertEqual(logs.records[0].getMessage(), "Outgoing request")
self.assertEqual(logs.records[0].levelname, "DEBUG")
self.assertFalse(OutgoingRequestsLog.objects.exists())

@override_settings(
LOG_OUTGOING_REQUESTS_ENABLED=True, LOG_OUTGOING_REQUESTS_DB_SAVE=False
)
def test_external_requests_are_logged_when_saving_disabled(self, m):
@override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=False)
def test_outgoing_requests_are_logged_when_saving_disabled(self, m):
self._setUpMocks(m)

with self.assertLogs("requests", level="DEBUG") as logs:
requests.get("http://example.com/some-path?version=2.0")

self.assertEqual(logs.output, ["DEBUG:requests:External request"])
self.assertEqual(logs.output, ["DEBUG:requests:Outgoing request"])
self.assertEqual(logs.records[0].name, "requests")
self.assertEqual(logs.records[0].getMessage(), "External request")
self.assertEqual(logs.records[0].getMessage(), "Outgoing request")
self.assertEqual(logs.records[0].levelname, "DEBUG")

@override_settings(
LOG_OUTGOING_REQUESTS_ENABLED=True, LOG_OUTGOING_REQUESTS_DB_SAVE=False
)
@override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=False)
def test_request_data_is_not_saved_when_saving_disabled(self, m):
self._setUpMocks(m)

Expand Down
Loading