Add API request logging

Pipfile

@@ -23,11 +23,12 @@ black = "*"
 factory_boy = "*"
 rich = "*"
 sphinx = "*"
-furo = "*"
 sphinx-autobuild = "*"
 sphinxcontrib-mermaid = "*"
-docutils = "==0.19"
-myst-parser = "*"
+# furo, myst-parser need to be pinned because
+# an underlying dependency, docutils needs a specific version of sphinx
+furo = "==2022.4.7"
+myst-parser = "==0.18.0"
 ansible-lint = "*"
 
 [packages]
@@ -96,4 +97,4 @@ django-convenient-formsets = "~=1.2.1"
 django-basicauth = "*"
 django-file-resubmit = "*"
 django-guardian = "*"
-docutils = "==0.19"
+drf-api-logger = "*"

apps/accounts/admin_site.py

@@ -285,3 +285,7 @@ def get_app_list(self, request):
 
 
 greenweb_admin = GreenWebAdmin(name="greenweb_admin")
+from drf_api_logger.models import APILogsModel
+from drf_api_logger.admin import APILogsAdmin
+
+greenweb_admin.register(APILogsModel, APILogsAdmin)

apps/greencheck/tests/test_api_logger.py

@@ -0,0 +1,51 @@
+import pytest
+import requests
+import time
+from django.urls import reverse
+
+from drf_api_logger.models import APILogsModel
+
+
+@pytest.mark.django_db
+@pytest.mark.uses_separate_logging_thread
+def test_api_requests_are_logged(live_server, transactional_db):
+    """
+    Check that API requests are logged. We need a live server, because the 
+    api request logger runs in a separate thread that is spun up only when 
+    the live server itself is running.
+    """
+
+    # when: a request has been made to our high traffic endpoint used for most greenchecks
+    res = requests.get(f"{live_server.url}{reverse('asn-list')}")
+
+    # Note: django api request logger works by logging API requests outside the normal 
+    # request lifecycle. By default, it writes to the db every 10 seconds, but the 
+    # minimum we can set this to is 1 seconds in testing.DRF_LOGGER_INTERVAL
+
+    # and: our api request logging interval has elapsed
+    time.sleep(1)
+
+    # then we should see one request logged
+    assert APILogsModel.objects.count() is 1
+
+
+@pytest.mark.django_db
+@pytest.mark.uses_separate_logging_thread
+def test_high_traffic_api_requests_are_not_logged(live_server):
+    """
+    Check we do not try to log requests on endpoints where it does not make sense to do so.
+    Some receive so much traffic that it would be impractical, for example.
+    """
+
+    # given: a request has been made to the high traffic endpoint use for most greenchecks
+    requests.get(f"{live_server.url}{reverse('green-domain-detail', args=['example.com'])}")
+
+    # and: a request has been made to our endpoint for generating images - which also sees a lot of use
+    requests.get(f"{live_server.url}{reverse('legacy-greencheck-image', args=['example.com'])}")
+
+    # and: our API request logger's logging interval has had time to log the requests
+    time.sleep(1)
+
+    # then: we should see no logged requests
+    assert APILogsModel.objects.count() is 0
+

greenweb/settings/common.py

@@ -103,6 +103,8 @@
     "widget_tweaks",
     # analysis
     "explorer",
+    # tracking inbound API usage
+    'drf_api_logger',
     # project specific
     "apps.theme",
     "apps.accounts",
@@ -139,10 +141,17 @@
     "django.contrib.auth.middleware.AuthenticationMiddleware",
     "django.contrib.messages.middleware.MessageMiddleware",
     "django.middleware.clickjacking.XFrameOptionsMiddleware",
+    'drf_api_logger.middleware.api_logger_middleware.APILoggerMiddleware',
     # see the section below on BASICAUTH
     "basicauth.middleware.BasicAuthMiddleware",
 ]
 
+DRF_API_LOGGER_DATABASE = True  # Default to False
+legacy_api_views = ["legacy-greencheck-image", "legacy-greencheck-multi", "legacy-directory-detail"]
+high_volume_views = ["green-domain-detail"]
+debugger_api_views = ["djdt:history_sidebar"]
+DRF_API_LOGGER_SKIP_URL_NAME = [ *legacy_api_views, *debugger_api_views, *high_volume_views]
+
 # set up django-guardian as authentcation backend
 AUTHENTICATION_BACKENDS = [
     "django.contrib.auth.backends.ModelBackend",  # this is a default value

greenweb/settings/testing.py

@@ -25,3 +25,5 @@
 
 # we replace this with the autogenerated address for a specific trello board in production
 TRELLO_REGISTRATION_EMAIL_TO_BOARD_ADDRESS = "mail-to-board@localhost"
+
+DRF_LOGGER_INTERVAL=1

pytest.ini

@@ -3,10 +3,11 @@
 ; so it can take precedent over any environment variables
 ; that might point DJANGO_SETTINGS_MODULE to development 
 ; or production, instead of the testings module
-addopts = --create-db --maxfail=0 -m "not smoke_test and not dramatiq and not flaky" --ds="greenweb.settings.testing"
+addopts = --create-db --maxfail=0 -m "not smoke_test and not dramatiq and not flaky and not uses_separate_logging_thread" --ds="greenweb.settings.testing"
 python_files = tests.py test_*.py *_tests.py
 markers =
-    only: Convenience method, so we can run a focussed test in pytest-watch
-    smoke_test: Smoke test - for exercising external APIs
-    object_storage: Uses object storage
-    flaky: Flaky tests that are hard to reproduce a failing result reliably
+    only: Convenience method, so we can run a focussed test in pytest-watch.
+    smoke_test: Smoke test - for exercising external APIs.
+    uses_separate_logging_thread: Relies on a thread working asynchronously - problematic for isolating tests from each other.
+    object_storage: Uses object storage.
+    flaky: Flaky tests that are hard to reproduce a failing result reliably.