feat(logs): each log line names its request, user and client address

A request gets nginx's $request_id (or a new one when it comes without a
valid one) and sends it back in X-Request-ID. The app log's lines carry
the logger, process and thread, the request ID, the signed-in user and the
client address; gunicorn's access lines carry the client address from
X-Real-IP and the same request ID, so the two logs can be joined.

conf/nginx/webvirtcloud.conf

@@ -25,6 +25,7 @@ server {
         proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
         proxy_set_header Host $http_host;
         proxy_set_header X-Forwarded-Proto $wvc_forwarded_proto;
+        proxy_set_header X-Request-ID $request_id;
         proxy_connect_timeout 1800;
         proxy_read_timeout 1800;
         proxy_send_timeout 1800;

gunicorn.conf.py

@@ -178,6 +178,9 @@ tmp_upload_dir = None
 logfile = '-'
 loglevel = 'info'
 accesslog = '-'
+# the client's address from nginx (gunicorn itself sees 127.0.0.1) and the
+# request's ID, as on the app log's lines
+access_log_format = '%({x-real-ip}i)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %({x-request-id}o)s'
 
 #
 # Process naming

webvirtcloud/log_context.py

@@ -0,0 +1,24 @@
+"""Each log line of a web request names the request, its user and its client
+address (set by webvirtcloud.middleware.RequestIdMiddleware)."""
+
+import contextvars
+import logging
+
+current_request = contextvars.ContextVar("current_request", default=None)
+
+
+class RequestFilter(logging.Filter):
+    """Adds request_id, user and ip to each record; "-" outside a web request."""
+
+    def filter(self, record):
+        request = current_request.get()
+        record.request_id = getattr(request, "request_id", "-")
+        record.ip = getattr(request, "client_ip", None) or "-"
+        record.user = "-"
+        try:
+            user = getattr(request, "user", None)
+            if user is not None and user.is_authenticated:
+                record.user = user.get_username()
+        except Exception:  # the user may be read from the database here; a failure must not lose the line
+            pass
+        return True

webvirtcloud/middleware.py

@@ -1,13 +1,21 @@
+import re
+import uuid
+
 from django.contrib import messages
 from django.http import JsonResponse
 from django.shortcuts import redirect, render
 from django.utils.http import url_has_allowed_host_and_scheme
 from django.utils.translation import gettext_lazy as _
 from libvirt import libvirtError
+from logs.audit import request_ip
 from operations import claims, jobs
 from operations.utils import busy_message, public_error_text, said, summary, words
 
+from webvirtcloud.log_context import current_request
+
 API_PREFIX = "/api/"
+# nginx's $request_id; any other value is replaced, so a client cannot write into the log
+REQUEST_ID = re.compile(r"[0-9a-f]{32}")
 # scripts only from this site: no inline script or event handler runs (inline styles still do);
 # the XML editor (Ace) and the API docs (Redoc) start their workers from blob: URLs
 CONTENT_SECURITY_POLICY = (
@@ -38,6 +46,23 @@ def error_text(request, exception):
     return public_error_text(exception)
 
 
+class RequestIdMiddleware:
+    """Names the request for its log lines (see log_context) and sends the ID back in X-Request-ID."""
+
+    def __init__(self, get_response):
+        self.get_response = get_response
+
+    def __call__(self, request):
+        request_id = request.headers.get("X-Request-ID", "")
+        request.request_id = request_id if REQUEST_ID.fullmatch(request_id) else uuid.uuid4().hex
+        request.client_ip = request_ip(request)
+        # not reset after the response: Django logs a 4xx or 5xx answer after the middleware returns
+        current_request.set(request)
+        response = self.get_response(request)
+        response["X-Request-ID"] = request.request_id
+        return response
+
+
 class ContentSecurityPolicyMiddleware:
     def __init__(self, get_response):
         self.get_response = get_response

webvirtcloud/settings.py.template

@@ -87,6 +87,7 @@ INSTALLED_APPS = [
 ]
 
 MIDDLEWARE = [
+    "webvirtcloud.middleware.RequestIdMiddleware",
     "django.middleware.security.SecurityMiddleware",
     "whitenoise.middleware.WhiteNoiseMiddleware",
     "django.contrib.sessions.middleware.SessionMiddleware",
@@ -248,9 +249,13 @@ LOGGING = {
     'disable_existing_loggers': False,
     'formatters': {
         'standard': {
-            'format': '[%(asctime)s] %(levelname)s: %(message)s'
+            'format': '[%(asctime)s] %(levelname)s %(name)s [%(process)d %(threadName)s] '
+                      '%(request_id)s %(user)s %(ip)s: %(message)s'
         },
     },
+    'filters': {
+        'request': {'()': 'webvirtcloud.log_context.RequestFilter'},
+    },
     'handlers': {
         'mail_admins': {
             'level': 'ERROR',
@@ -263,6 +268,7 @@ LOGGING = {
             'maxBytes': 10 * 1024 * 1024,
             'backupCount': 5,
             'formatter': 'standard',
+            'filters': ['request'],
         },
     },
     'loggers': {

webvirtcloud/tests/test_logging.py

@@ -1,10 +1,17 @@
 """The app log is bounded (rotates) and written to a deterministic absolute
 path, not the process working directory."""
 
+import io
+import logging
 import os
 
 from django.conf import settings
-from django.test import TestCase
+from django.contrib.auth.models import User
+from django.http import HttpResponse
+from django.test import RequestFactory, TestCase
+
+from webvirtcloud.log_context import RequestFilter
+from webvirtcloud.middleware import RequestIdMiddleware
 
 
 class LoggingConfigTestCase(TestCase):
@@ -38,3 +45,30 @@ class LoggingConfigTestCase(TestCase):
         )
         self.assertEqual(result.returncode, 0, result.stderr)
         self.assertTrue(os.path.isdir(os.path.dirname(log)), log)
+
+
+class RequestIdTestCase(TestCase):
+    def test_a_line_of_a_request_names_the_request_user_and_address(self):
+        stream = io.StringIO()
+        handler = logging.StreamHandler(stream)
+        handler.addFilter(RequestFilter())
+        handler.setFormatter(logging.Formatter(settings.LOGGING["formatters"]["standard"]["format"]))
+        logger = logging.getLogger("webvirtcloud.tests.request")
+        logger.addHandler(handler)
+        self.addCleanup(logger.removeHandler, handler)
+
+        def view(request):
+            logger.warning("refused")
+            return HttpResponse()
+
+        # from nginx: its request ID, the client in X-Real-IP
+        request = RequestFactory().get("/", HTTP_X_REQUEST_ID="0123456789abcdef" * 2, HTTP_X_REAL_IP="192.0.2.7")
+        request.user = User.objects.create_user("alice")
+        response = RequestIdMiddleware(view)(request)
+
+        self.assertEqual(response["X-Request-ID"], "0123456789abcdef" * 2)
+        self.assertIn(f"{'0123456789abcdef' * 2} alice 192.0.2.7: refused", stream.getvalue())
+
+    def test_an_id_sent_by_a_client_cannot_write_into_the_log(self):
+        response = self.client.get("/accounts/login/", HTTP_X_REQUEST_ID="x\n[forged] line")
+        self.assertRegex(response["X-Request-ID"], r"^[0-9a-f]{32}$")