From fdd731029742e36c04c32540c688cec47b68f360 Mon Sep 17 00:00:00 2001 From: catborise Date: Thu, 5 Nov 2026 14:36:58 +0300 Subject: [PATCH] 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 | 1 + gunicorn.conf.py | 3 +++ webvirtcloud/log_context.py | 24 ++++++++++++++++++++ webvirtcloud/middleware.py | 25 +++++++++++++++++++++ webvirtcloud/settings.py.template | 8 ++++++- webvirtcloud/tests/test_logging.py | 36 +++++++++++++++++++++++++++++- 6 files changed, 95 insertions(+), 2 deletions(-) create mode 100644 webvirtcloud/log_context.py diff --git a/conf/nginx/webvirtcloud.conf b/conf/nginx/webvirtcloud.conf index f26e70e3..1dda01ab 100644 --- a/conf/nginx/webvirtcloud.conf +++ b/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; diff --git a/gunicorn.conf.py b/gunicorn.conf.py index be0084af..6a8b8084 100644 --- a/gunicorn.conf.py +++ b/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 diff --git a/webvirtcloud/log_context.py b/webvirtcloud/log_context.py new file mode 100644 index 00000000..df664d33 --- /dev/null +++ b/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 diff --git a/webvirtcloud/middleware.py b/webvirtcloud/middleware.py index dddf29d2..aa929c49 100644 --- a/webvirtcloud/middleware.py +++ b/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 diff --git a/webvirtcloud/settings.py.template b/webvirtcloud/settings.py.template index ff43b1d8..10ef1c05 100644 --- a/webvirtcloud/settings.py.template +++ b/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': { diff --git a/webvirtcloud/tests/test_logging.py b/webvirtcloud/tests/test_logging.py index 711082c9..9e525408 100644 --- a/webvirtcloud/tests/test_logging.py +++ b/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}$")