Closes #23656: Add a dedicated logger for GraphQL API requests

docs/configuration/system.md

@@ -247,6 +247,7 @@ LOGGING = {
 * `netbox.auth.*` - Authentication events
 * `netbox.api.views.*` - Views which handle business logic for the REST API
 * `netbox.event_rules` - Event rules
+* `netbox.graphql.query` - GraphQL API requests (logged at `INFO`)
 * `netbox.jobs.*` - Background jobs
 * `netbox.reports.*` - Report execution (`module.name`)
 * `netbox.scripts.*` - Custom script execution (`module.name`)

netbox/netbox/graphql/extensions.py

@@ -0,0 +1,124 @@
+import hashlib
+import json
+import logging
+import time
+
+from graphql.language import (
+    FloatValueNode,
+    IntValueNode,
+    ListValueNode,
+    ObjectValueNode,
+    StringValueNode,
+    Visitor,
+    print_ast,
+    visit,
+)
+from graphql.utilities import strip_ignored_characters
+from strawberry.extensions import SchemaExtension
+
+from utilities.request import get_client_ip
+
+__all__ = (
+    'QueryLogger',
+    'normalize_query',
+)
+
+logger = logging.getLogger('netbox.graphql.query')
+
+
+class LiteralValueStripper(Visitor):
+    """
+    Replace literal argument values with fixed placeholders, so that queries differing only in the values they pass
+    produce the same document. Variables, enums, booleans and nulls are kept, as are the keys of input objects.
+    """
+    def enter_string_value(self, node, *args):
+        return StringValueNode(value='')
+
+    def enter_int_value(self, node, *args):
+        return IntValueNode(value='0')
+
+    def enter_float_value(self, node, *args):
+        return FloatValueNode(value='0')
+
+    def leave_list_value(self, node, *args):
+        # A list of scalars collapses to an empty list so that its length doesn't matter. Lists of input objects
+        # (e.g. OR clauses in a filter) are kept, since their structure is part of the query shape.
+        if any(isinstance(value, (ListValueNode, ObjectValueNode)) for value in node.values):
+            return None
+        return ListValueNode(values=())
+
+
+def normalize_query(document):
+    """
+    Return the given GraphQL document as a single line, with its literal argument values replaced by placeholders.
+    """
+    return strip_ignored_characters(print_ast(visit(document, LiteralValueStripper())))
+
+
+class QueryLogger(SchemaExtension):
+    """
+    Log each GraphQL operation to the `netbox.graphql.query` logger. Does nothing unless that logger is enabled for
+    INFO messages.
+    """
+    def on_operation(self):
+        if not logger.isEnabledFor(logging.INFO):
+            yield
+            return
+
+        start = time.perf_counter()
+        yield
+        duration = (time.perf_counter() - start) * 1000
+
+        execution_context = self.execution_context
+        request = getattr(execution_context.context, 'request', None)
+
+        # Identify the user, token, and client
+        user = getattr(request, 'user', None)
+        token = getattr(request, 'auth', None)
+        try:
+            client_ip = get_client_ip(request) if request is not None else None
+        except ValueError:
+            client_ip = None
+
+        # Normalize the query (if it could be parsed)
+        if execution_context.graphql_document is not None:
+            query = normalize_query(execution_context.graphql_document)
+            query_hash = hashlib.sha256(query.encode()).hexdigest()
+        else:
+            query = query_hash = None
+
+        # Summarize the result
+        result = execution_context.result
+        errors = (result.errors if result else None) or execution_context.pre_execution_errors or []
+        if result is not None and result.data is not None:
+            response_size = len(json.dumps(result.data, default=str).encode())
+        else:
+            response_size = 0
+
+        data = {
+            'user': user.username if user is not None and user.is_authenticated else None,
+            'token_id': getattr(token, 'pk', None),
+            'client_ip': str(client_ip) if client_ip else None,
+            'operation_name': execution_context.operation_name,
+            'query_hash': query_hash,
+            'query': query,
+            'variables': execution_context.variables,
+            'duration_ms': round(duration, 1),
+            'error_count': len(errors),
+            'response_size': response_size,
+        }
+        logger.info(
+            "user=%s token_id=%s client_ip=%s operation_name=%s query_hash=%s duration_ms=%s error_count=%s "
+            "response_size=%s query=%s variables=%s",
+            data['user'],
+            data['token_id'],
+            data['client_ip'],
+            data['operation_name'],
+            data['query_hash'],
+            data['duration_ms'],
+            data['error_count'],
+            data['response_size'],
+            data['query'],
+            json.dumps(data['variables'], default=str),
+            extra={'graphql': data},
+        )

netbox/netbox/graphql/schema.py

@@ -19,6 +19,7 @@ from virtualization.graphql.schema import VirtualizationQuery
 from vpn.graphql.schema import VPNQuery
 from wireless.graphql.schema import WirelessQuery
 
+from .extensions import QueryLogger
 from .scalars import BigInt, BigIntScalar
 from .utils import validate_extension_targets
 
@@ -51,6 +52,7 @@ def get_schema_extensions() -> list[SchemaExtensionFactory]:
     max_depth = settings.GRAPHQL_MAX_QUERY_DEPTH
 
     extensions: list[SchemaExtensionFactory] = [
+        QueryLogger,
         lambda: DjangoOptimizerExtension(prefetch_custom_queryset=True),
         lambda: MaxAliasesLimiter(max_alias_count=max_aliases),
     ]

netbox/netbox/graphql/views.py

@@ -30,6 +30,7 @@ class NetBoxGraphQLView(GraphQLView):
                 auth_info = authenticator.authenticate(request)
                 if auth_info is not None:
                     request.user = auth_info[0]  # User object
+                    request.auth = auth_info[1]  # Token object
             except AuthenticationFailed as exc:
                 return HttpResponseForbidden(exc.detail)
 

netbox/netbox/tests/test_graphql.py

@@ -1,4 +1,6 @@
+import hashlib
 import json
+import logging
 import re
 from types import SimpleNamespace
 from unittest import mock, skipIf
@@ -13,6 +15,7 @@ from django.test import override_settings
 from django.test.utils import CaptureQueriesContext
 from django.urls import reverse
 from django.utils import timezone
+from graphql import parse
 from rest_framework import status
 from strawberry.extensions import QueryDepthLimiter
 from strawberry.schema.config import StrawberryConfig
@@ -38,6 +41,7 @@ from dcim.models import (
 from extras.choices import CustomFieldTypeChoices
 from extras.models import CustomField, ExportTemplate, JournalEntry, TableConfig, Tag
 from ipam.models import ASN, RIR, VLAN, Aggregate, IPAddress, Prefix
+from netbox.graphql.extensions import normalize_query
 from netbox.graphql.pagination import apply_distinct_window_pagination
 from netbox.graphql.scalars import BigInt, BigIntScalar
 from netbox.graphql.schema import Query, get_schema_extensions, schema
@@ -1512,6 +1516,133 @@ class GraphQLAPITestCase(APITestCase):
         self.assertEqual(data['errors'][0]['message'], 'Cannot specify both `start` and `offset` in pagination.')
 
 
+class GraphQLQueryLoggerTestCase(APITestCase):
+
+    @classmethod
+    def setUpTestData(cls):
+        Site.objects.create(name='Site 1', slug='site-1')
+
+    def setUp(self):
+        super().setUp()
+        self.add_permissions('dcim.view_site')
+
+    def _post(self, data, **kwargs):
+        return self.client.post(reverse('graphql'), data=data, format='json', **kwargs)
+
+    def test_operation_logged(self):
+        """
+        Each operation is logged with the user, token, client, normalized query and result summary.
+        """
+        query = (
+            'query SiteNames($limit: Int) { '
+            'site_list(filters: {name: {exact: "Site 1"}}, pagination: {limit: $limit}) { name } }'
+        )
+        with self.assertLogs('netbox.graphql.query', level='INFO') as cm:
+            response = self._post({'query': query, 'variables': {'limit': 5}}, **self.header)
+        self.assertHttpStatus(response, status.HTTP_200_OK)
+
+        self.assertEqual(len(cm.records), 1)
+        data = cm.records[0].graphql
+        expected_query = (
+            'query SiteNames($limit:Int){site_list(filters:{name:{exact:""}}pagination:{limit:$limit}){name}}'
+        )
+        self.assertEqual(data['user'], self.user.username)
+        self.assertEqual(data['token_id'], self.token.pk)
+        self.assertEqual(data['client_ip'], '127.0.0.1')
+        self.assertEqual(data['operation_name'], 'SiteNames')
+        self.assertEqual(data['query'], expected_query)
+        self.assertEqual(data['query_hash'], hashlib.sha256(expected_query.encode()).hexdigest())
+        self.assertEqual(data['variables'], {'limit': 5})
+        self.assertEqual(data['error_count'], 0)
+        self.assertEqual(data['response_size'], len(b'{"site_list": [{"name": "Site 1"}]}'))
+        self.assertGreaterEqual(data['duration_ms'], 0)
+        self.assertIn('operation_name=SiteNames', cm.output[0])
+        self.assertNotIn('Site 1', cm.output[0])
+
+    def test_session_authentication_has_no_token(self):
+        """
+        Operations from a session-authenticated user are logged without a token ID.
+        """
+        self.client.force_login(self.user)
+        with self.assertLogs('netbox.graphql.query', level='INFO') as cm:
+            self._post({'query': '{ site_list { name } }'})
+
+        data = cm.records[0].graphql
+        self.assertEqual(data['user'], self.user.username)
+        self.assertIsNone(data['token_id'])
+        self.assertIsNone(data['operation_name'])
+
+    def test_errors_counted(self):
+        """
+        Errors raised before execution (e.g. validation failures) are counted.
+        """
+        with self.assertLogs('netbox.graphql.query', level='INFO') as cm:
+            self._post({'query': '{ site_list { name invalid_field } }'}, **self.header)
+
+        data = cm.records[0].graphql
+        self.assertEqual(data['error_count'], 1)
+        self.assertEqual(data['response_size'], 0)
+        self.assertEqual(data['query'], '{site_list{name invalid_field}}')
+
+    def test_unparseable_query(self):
+        """
+        A query which can't be parsed is logged without a normalized query.
+        """
+        with self.assertLogs('netbox.graphql.query', level='INFO') as cm:
+            self._post({'query': '{ site_list {'}, **self.header)
+
+        data = cm.records[0].graphql
+        self.assertEqual(data['error_count'], 1)
+        self.assertIsNone(data['query'])
+        self.assertIsNone(data['query_hash'])
+
+    def test_disabled_logger_does_nothing(self):
+        """
+        The extension does no work when the logger isn't enabled for INFO messages.
+        """
+        logger = logging.getLogger('netbox.graphql.query')
+        level = logger.level
+        logger.setLevel(logging.WARNING)
+        try:
+            with mock.patch('netbox.graphql.extensions.normalize_query') as normalize_query:
+                response = self._post({'query': '{ site_list { name } }'}, **self.header)
+        finally:
+            logger.setLevel(level)
+        self.assertHttpStatus(response, status.HTTP_200_OK)
+        normalize_query.assert_not_called()
+
+
+class NormalizeQueryTestCase(TestCase):
+
+    def test_literals_replaced(self):
+        query = (
+            '{ site_list(filters: {name: {exact: "Site 1"}, id: {in_list: [1, 2, 3]}, status: STATUS_ACTIVE}, '
+            'pagination: {limit: 10, offset: 2}) { id } }'
+        )
+        self.assertEqual(
+            normalize_query(parse(query)),
+            '{site_list(filters:{name:{exact:""}id:{in_list:[]}status:STATUS_ACTIVE}'
+            'pagination:{limit:0 offset:0}){id}}',
+        )
+
+    def test_values_do_not_affect_shape(self):
+        query_a = '{ site_list(filters: {name: {exact: "Site 1"}, id: {in_list: [1, 2, 3]}}) { id } }'
+        query_b = '{ site_list(filters: {name: {exact: "Site 2"}, id: {in_list: [4]}}) { id } }'
+        self.assertEqual(normalize_query(parse(query_a)), normalize_query(parse(query_b)))
+
+    def test_structure_affects_shape(self):
+        query_a = '{ site_list(filters: {name: {exact: "Site 1"}}) { id } }'
+        query_b = '{ site_list(filters: {slug: {exact: "Site 1"}}) { id } }'
+        self.assertNotEqual(normalize_query(parse(query_a)), normalize_query(parse(query_b)))
+
+    def test_lists_of_objects_kept(self):
+        query = '{ site_list(filters: {OR: [{name: {exact: "a"}}, {slug: {exact: "b"}}]}) { id } }'
+        self.assertEqual(
+            normalize_query(parse(query)),
+            '{site_list(filters:{OR:[{name:{exact:""}}{slug:{exact:""}}]}){id}}',
+        )
+
+
 class GraphQLDeferredColumnTestCase(APITestCase):
     """
     A GraphQL field backed by a custom resolver is opaque to the query optimizer, which narrows column