Address review feedback: cheaper response size, normalization cache, sanitized operation name

docs/configuration/system.md

@@ -247,7 +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.graphql.query` - GraphQL API requests (logged at `INFO`; see [GraphQL API logging](../integrations/graphql-api.md#logging))
 * `netbox.jobs.*` - Background jobs
 * `netbox.reports.*` - Report execution (`module.name`)
 * `netbox.scripts.*` - Custom script execution (`module.name`)

docs/integrations/graphql-api.md

@@ -200,6 +200,36 @@ This will return up to 20 records with an ID greater than or equal to 124.
 
 NetBox's GraphQL API uses the same API authentication tokens as its REST API. See the [REST API authentication](./rest-api.md#authentication) documentation for further detail.
 
+## Logging
+
+NetBox can log each GraphQL request to the `netbox.graphql.query` logger at the `INFO` level. This logger is not enabled by default; to enable it, configure it under the [`LOGGING`](../configuration/system.md#logging) configuration parameter:
+
+```python
+LOGGING = {
+    'version': 1,
+    'handlers': {
+        'graphql': {
+            'class': 'logging.FileHandler',
+            'filename': '/var/log/netbox/graphql.log',
+        },
+    },
+    'loggers': {
+        'netbox.graphql.query': {
+            'handlers': ['graphql'],
+            'level': 'INFO',
+        },
+    },
+}
+```
+
+Each record includes the user, the API token ID (if a token was used), the client IP address, the operation name, the query, the query variables, the time taken, the number of errors, and the size of the response in bytes. The query is logged with its literal values replaced by placeholders (e.g. `name: "foo"` becomes `name: ""`), along with a hash of the result, so that identical queries can be grouped. The query and variables are each truncated to 4096 characters. These fields are also attached to each log record as a dictionary named `graphql`, for use by structured log formatters.
+
+!!! warning
+    Query variables are logged as submitted. If clients pass sensitive values as variables, those values will be written to the log.
+
+!!! tip
+    Log records are written as part of each request. On busy installations, consider using a [`QueueHandler`](https://docs.python.org/3/library/logging.handlers.html#queuehandler) so that slow log destinations don't delay API responses.
+
 ## Disabling the GraphQL API
 
 If not needed, the GraphQL API can be disabled by setting the [`GRAPHQL_ENABLED`](../configuration/graphql-api.md#graphql_enabled) configuration parameter to False and restarting NetBox.

netbox/netbox/graphql/extensions.py

@@ -1,13 +1,13 @@
 import hashlib
 import json
 import logging
+import threading
 import time
 
 from graphql.language import (
     FloatValueNode,
     IntValueNode,
     ListValueNode,
-    ObjectValueNode,
     StringValueNode,
     Visitor,
     print_ast,
@@ -20,11 +20,21 @@ from utilities.request import get_client_ip
 
 __all__ = (
     'QueryLogger',
+    'log_graphql_queries',
     'normalize_query',
 )
 
 logger = logging.getLogger('netbox.graphql.query')
 
+# Maximum length of the query and variables written to a log record
+MAX_LOGGED_LENGTH = 4096
+
+# Maximum number of normalized queries to cache
+NORMALIZED_QUERY_CACHE_SIZE = 512
+
+# Attribute on the request where QueryLogger leaves records for the view to complete and emit
+REQUEST_ATTR = '_graphql_query_log'
+
 
 class LiteralValueStripper(Visitor):
     """
@@ -41,11 +51,11 @@ class LiteralValueStripper(Visitor):
         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=())
+        # A list of placeholders collapses to an empty list so that its length doesn't matter. Lists containing any
+        # other values (variables, enums, input objects, etc.) are kept, since those are part of the query shape.
+        if all(isinstance(value, (StringValueNode, IntValueNode, FloatValueNode)) for value in node.values):
+            return ListValueNode(values=())
+        return None
 
 
 def normalize_query(document):
@@ -55,10 +65,74 @@ def normalize_query(document):
     return strip_ignored_characters(print_ast(visit(document, LiteralValueStripper())))
 
 
+_normalized_queries = {}
+_normalized_queries_lock = threading.Lock()
+
+
+def _normalize_query_text(query, document):
+    """
+    Return the normalized form of the given query (and its parsed document) along with its hash. Clients typically
+    send the same query text repeatedly (passing values as variables), so the result is cached by query text.
+    """
+    if (cached := _normalized_queries.get(query)) is not None:
+        return cached
+    normalized = normalize_query(document)
+    cached = (normalized, hashlib.sha256(normalized.encode()).hexdigest())
+    with _normalized_queries_lock:
+        if len(_normalized_queries) >= NORMALIZED_QUERY_CACHE_SIZE:
+            # Evict the oldest entry
+            _normalized_queries.pop(next(iter(_normalized_queries)), None)
+        _normalized_queries[query] = cached
+    return cached
+
+
+def _truncate(value):
+    if value is not None and len(value) > MAX_LOGGED_LENGTH:
+        return f'{value[:MAX_LOGGED_LENGTH]}...'
+    return value
+
+
+def _emit(record):
+    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",
+        record['user'],
+        record['token_id'],
+        record['client_ip'],
+        json.dumps(record['operation_name']),  # Client-supplied; encode to prevent log forging
+        record['query_hash'],
+        record['duration_ms'],
+        record['error_count'],
+        record['response_size'],
+        record['query'],
+        _truncate(json.dumps(record['variables'], default=str)),
+        extra={'graphql': record},
+    )
+
+
+def log_graphql_queries(request, response):
+    """
+    Complete and emit any records left on the request by QueryLogger, adding the response size and the total time
+    taken (including serialization of the response).
+    """
+    records = getattr(request, REQUEST_ATTR, None)
+    if not records:
+        return
+    response_size = None if getattr(response, 'streaming', False) else len(response.content)
+    end = time.perf_counter()
+    for record, start in records:
+        record['duration_ms'] = round((end - start) * 1000, 1)
+        record['response_size'] = response_size
+        _emit(record)
+
+
 class QueryLogger(SchemaExtension):
     """
     Log each GraphQL operation to the `netbox.graphql.query` logger. Does nothing unless that logger is enabled for
     INFO messages.
+
+    The record is left on the request, to be emitted by the view once the response has been rendered (see
+    log_graphql_queries()). Operations executed without a request are logged immediately, without a response size.
     """
     def on_operation(self):
         if not logger.isEnabledFor(logging.INFO):
@@ -66,9 +140,15 @@ class QueryLogger(SchemaExtension):
             return
 
         start = time.perf_counter()
-        yield
-        duration = (time.perf_counter() - start) * 1000
+        try:
+            yield
+        except Exception:
+            # The operation could not be executed (e.g. the requested operation name doesn't exist in the document)
+            self._record(start, failed=True)
+            raise
+        self._record(start)
 
+    def _record(self, start, failed=False):
         execution_context = self.execution_context
         request = getattr(execution_context.context, 'request', None)
 
@@ -81,21 +161,17 @@ class QueryLogger(SchemaExtension):
             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()
+        if execution_context.graphql_document is not None and execution_context.query:
+            query, query_hash = _normalize_query_text(execution_context.query, execution_context.graphql_document)
+            query = _truncate(query)
         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
+        error_count = len(errors) or int(failed)
 
-        data = {
+        record = {
             '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,
@@ -103,22 +179,15 @@ class QueryLogger(SchemaExtension):
             'query_hash': query_hash,
             'query': query,
             'variables': execution_context.variables,
-            'duration_ms': round(duration, 1),
-            'error_count': len(errors),
-            'response_size': response_size,
+            'duration_ms': None,
+            'error_count': error_count,
+            'response_size': None,
         }
-        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},
-        )
+
+        if request is None:
+            record['duration_ms'] = round((time.perf_counter() - start) * 1000, 1)
+            _emit(record)
+        else:
+            if not hasattr(request, REQUEST_ATTR):
+                setattr(request, REQUEST_ATTR, [])
+            getattr(request, REQUEST_ATTR).append((record, start))

netbox/netbox/graphql/views.py

@@ -8,6 +8,7 @@ from strawberry.django.views import GraphQLView
 
 from netbox.api.authentication import TokenAuthentication
 from netbox.config import get_config
+from netbox.graphql.extensions import log_graphql_queries
 
 
 class NetBoxGraphQLView(GraphQLView):
@@ -40,4 +41,7 @@ class NetBoxGraphQLView(GraphQLView):
                 return redirect_to_login(reverse('graphql'))
             return HttpResponseForbidden("No credentials provided.")
 
-        return super().dispatch(request, *args, **kwargs)
+        response = super().dispatch(request, *args, **kwargs)
+        log_graphql_queries(request, response)
+
+        return response

netbox/netbox/tests/test_graphql.py

@@ -41,7 +41,12 @@ 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.extensions import (
+    MAX_LOGGED_LENGTH,
+    _normalize_query_text,
+    _normalized_queries,
+    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
@@ -1554,9 +1559,9 @@ class GraphQLQueryLoggerTestCase(APITestCase):
         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.assertEqual(data['response_size'], len(response.content))
         self.assertGreaterEqual(data['duration_ms'], 0)
-        self.assertIn('operation_name=SiteNames', cm.output[0])
+        self.assertIn('operation_name="SiteNames"', cm.output[0])
         self.assertNotIn('Site 1', cm.output[0])
 
     def test_session_authentication_has_no_token(self):
@@ -1577,11 +1582,11 @@ class GraphQLQueryLoggerTestCase(APITestCase):
         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)
+            response = 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['response_size'], len(response.content))
         self.assertEqual(data['query'], '{site_list{name invalid_field}}')
 
     def test_unparseable_query(self):
@@ -1596,6 +1601,70 @@ class GraphQLQueryLoggerTestCase(APITestCase):
         self.assertIsNone(data['query'])
         self.assertIsNone(data['query_hash'])
 
+    def test_operation_name_encoded(self):
+        """
+        A client-supplied operation name can't inject additional lines into the log.
+        """
+        operation_name = 'x\nuser=admin token_id=1 operation_name=ok'
+        with self.assertLogs('netbox.graphql.query', level='INFO') as cm:
+            # The supplied operation name is reported as-is when the query can't be parsed
+            self._post({'query': '{ site_list {', 'operationName': operation_name}, **self.header)
+
+        self.assertEqual(cm.records[0].graphql['operation_name'], operation_name)
+        self.assertNotIn('\n', cm.output[0])
+        self.assertIn(f'operation_name={json.dumps(operation_name)}', cm.output[0])
+
+    def test_unknown_operation_name(self):
+        """
+        An operation which can't be executed (here, because the named operation doesn't exist) is still logged.
+        """
+        with self.assertLogs('netbox.graphql.query', level='INFO') as cm:
+            response = self._post({'query': 'query A { site_list { name } }', 'operationName': 'B'}, **self.header)
+        self.assertHttpStatus(response, status.HTTP_400_BAD_REQUEST)
+
+        data = cm.records[0].graphql
+        self.assertEqual(data['operation_name'], 'B')
+        self.assertEqual(data['query'], 'query A{site_list{name}}')
+        self.assertEqual(data['error_count'], 1)
+        self.assertEqual(data['response_size'], len(response.content))
+
+    def test_long_values_truncated(self):
+        """
+        Long queries and variables are truncated in the log message.
+        """
+        name = 'x' * (MAX_LOGGED_LENGTH * 2)
+        query = f'query ($name: [String!]) {{ site_list(filters: {{name: {{in_list: $name}}}}) {{ {name}: name }} }}'
+        with self.assertLogs('netbox.graphql.query', level='INFO') as cm:
+            self._post({'query': query, 'variables': {'name': [name]}}, **self.header)
+
+        data = cm.records[0].graphql
+        self.assertEqual(len(data['query']), MAX_LOGGED_LENGTH + 3)
+        self.assertTrue(data['query'].endswith('...'))
+        self.assertLess(len(cm.output[0]), MAX_LOGGED_LENGTH * 3)
+
+    def test_normalization_cached(self):
+        """
+        Repeated queries are normalized once.
+        """
+        query = '{ site_list(filters: {name: {exact: "cache test"}}) { name } }'
+        with self.assertLogs('netbox.graphql.query', level='INFO'):
+            self._post({'query': query}, **self.header)
+            with mock.patch('netbox.graphql.extensions.normalize_query') as normalize_query:
+                self._post({'query': query}, **self.header)
+        normalize_query.assert_not_called()
+
+    def test_operation_without_request(self):
+        """
+        Operations executed without a request are logged immediately, without a response size.
+        """
+        with self.assertLogs('netbox.graphql.query', level='INFO') as cm:
+            schema.execute_sync('{ __typename }', context_value=SimpleNamespace())
+
+        data = cm.records[0].graphql
+        self.assertEqual(data['query'], '{__typename}')
+        self.assertIsNone(data['response_size'])
+        self.assertIsNotNone(data['duration_ms'])
+
     def test_disabled_logger_does_nothing(self):
         """
         The extension does no work when the logger isn't enabled for INFO messages.
@@ -1604,12 +1673,16 @@ class GraphQLQueryLoggerTestCase(APITestCase):
         level = logger.level
         logger.setLevel(logging.WARNING)
         try:
-            with mock.patch('netbox.graphql.extensions.normalize_query') as normalize_query:
+            with (
+                mock.patch('netbox.graphql.extensions._normalize_query_text') as normalize_query_text,
+                mock.patch('netbox.graphql.extensions.get_client_ip') as get_client_ip,
+            ):
                 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()
+        normalize_query_text.assert_not_called()
+        get_client_ip.assert_not_called()
 
 
 class NormalizeQueryTestCase(TestCase):
@@ -1642,6 +1715,27 @@ class NormalizeQueryTestCase(TestCase):
             '{site_list(filters:{OR:[{name:{exact:""}}{slug:{exact:""}}]}){id}}',
         )
 
+    def test_lists_of_variables_and_enums_kept(self):
+        query = (
+            'query ($status: String) { site_list(filters: {status: {in_list: [$status]}}) { id } '
+            'location_list(filters: {status: {in_list: [STATUS_ACTIVE, STATUS_PLANNED]}}) { id } }'
+        )
+        self.assertEqual(
+            normalize_query(parse(query)),
+            'query($status:String){site_list(filters:{status:{in_list:[$status]}}){id}'
+            'location_list(filters:{status:{in_list:[STATUS_ACTIVE STATUS_PLANNED]}}){id}}',
+        )
+
+    def test_cache_bounded(self):
+        queries = [f'{{ {alias}: site_list {{ id }} }}' for alias in ('a', 'b', 'c')]
+        with (
+            mock.patch('netbox.graphql.extensions.NORMALIZED_QUERY_CACHE_SIZE', 2),
+            mock.patch.dict(_normalized_queries, clear=True),
+        ):
+            for query in queries:
+                _normalize_query_text(query, parse(query))
+            self.assertEqual(list(_normalized_queries), queries[1:])
+
 
 class GraphQLDeferredColumnTestCase(APITestCase):
     """