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

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`; 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

@@ -0,0 +1,209 @@
+import hashlib
+import json
+import logging
+import threading
+import time
+
+from graphql.language import (
+    FloatValueNode,
+    IntValueNode,
+    ListValueNode,
+    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',
+    '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):
+    """
+    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 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):
+    """
+    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())))
+
+
+_normalized_queries = {}
+_normalized_queries_lock = threading.Lock()
+
+
+def _truncate(value):
+    if value is not None and len(value) > MAX_LOGGED_LENGTH:
+        return f'{value[:MAX_LOGGED_LENGTH]}...'
+    return value
+
+
+def _normalize_query_text(query, document):
+    """
+    Return the normalized form of the given query (and its parsed document), truncated for logging, along with the
+    hash of the full normalized query. Clients typically send the same query text repeatedly (passing values as
+    variables), so the result is cached. The cache is keyed on a digest of the query text, so that large queries don't
+    occupy memory.
+    """
+    key = hashlib.sha256(query.encode()).digest()
+    if (cached := _normalized_queries.get(key)) is not None:
+        return cached
+    normalized = normalize_query(document)
+    cached = (_truncate(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[key] = cached
+    return cached
+
+
+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",
+        json.dumps(record['user']),  # Encode to prevent log forging
+        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
+    try:
+        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)
+    except Exception:
+        # Never let a logging failure affect the response
+        logger.exception("Failed to log GraphQL operation")
+
+
+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):
+            yield
+            return
+
+        start = time.perf_counter()
+        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):
+        try:
+            record = self._get_record(failed)
+            request = getattr(self.execution_context.context, 'request', None)
+            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))
+        except Exception:
+            # Never let a logging failure affect the operation (or replace the exception it raised)
+            logger.exception("Failed to log GraphQL operation")
+
+    def _get_record(self, failed):
+        """
+        Return the details of the operation to be logged.
+        """
+        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 and execution_context.query:
+            query, query_hash = _normalize_query_text(execution_context.query, execution_context.graphql_document)
+        else:
+            query = query_hash = None
+
+        result = execution_context.result
+        errors = (result.errors if result else None) or execution_context.pre_execution_errors or []
+        error_count = len(errors) or int(failed)
+
+        return {
+            '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': None,
+            'error_count': error_count,
+            'response_size': None,
+        }

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

@@ -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):
@@ -30,6 +31,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)
 
@@ -39,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

@@ -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,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 (
+    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
@@ -1512,6 +1521,266 @@ 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(response.content))
+        self.assertGreaterEqual(data['duration_ms'], 0)
+        self.assertIn(f'user={json.dumps(self.user.username)}', 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):
+        """
+        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:
+            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'], len(response.content))
+        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_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.
+        """
+        logger = logging.getLogger('netbox.graphql.query')
+        level = logger.level
+        logger.setLevel(logging.WARNING)
+        try:
+            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_text.assert_not_called()
+        get_client_ip.assert_not_called()
+
+    def test_logging_failure_does_not_affect_operation(self):
+        """
+        An error while logging an operation is logged, and doesn't affect the response.
+        """
+        with (
+            self.assertLogs('netbox.graphql.query', level='INFO') as cm,
+            mock.patch('netbox.graphql.extensions._normalize_query_text', side_effect=RuntimeError),
+        ):
+            response = self._post({'query': '{ site_list { name } }'}, **self.header)
+            # An operation which fails keeps its own error
+            failed_response = self._post(
+                {'query': 'query A { site_list { name } }', 'operationName': 'B'}, **self.header
+            )
+        self.assertHttpStatus(response, status.HTTP_200_OK)
+        self.assertEqual(response.json()['data'], {'site_list': [{'name': 'Site 1'}]})
+        self.assertHttpStatus(failed_response, status.HTTP_400_BAD_REQUEST)
+        self.assertEqual(
+            [record.getMessage() for record in cm.records],
+            ['Failed to log GraphQL operation', 'Failed to log GraphQL operation'],
+        )
+
+    def test_emit_failure_does_not_affect_response(self):
+        with (
+            self.assertLogs('netbox.graphql.query', level='INFO') as cm,
+            mock.patch('netbox.graphql.extensions._emit', side_effect=RuntimeError),
+        ):
+            response = self._post({'query': '{ site_list { name } }'}, **self.header)
+        self.assertHttpStatus(response, status.HTTP_200_OK)
+        self.assertEqual(cm.records[0].getMessage(), 'Failed to log GraphQL operation')
+
+
+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}}',
+        )
+
+    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), [hashlib.sha256(query.encode()).digest() for query in queries[1:]]
+            )
+
+    def test_cache_holds_truncated_query(self):
+        """
+        The cache holds the normalized query truncated for logging, and the hash of the full normalized query.
+        """
+        query = f'{{ site_list {{ {"x" * MAX_LOGGED_LENGTH * 2}: name }} }}'
+        with mock.patch.dict(_normalized_queries, clear=True):
+            normalized, query_hash = _normalize_query_text(query, parse(query))
+            self.assertEqual(len(normalized), MAX_LOGGED_LENGTH + 3)
+            self.assertEqual(query_hash, hashlib.sha256(normalize_query(parse(query)).encode()).hexdigest())
+            self.assertEqual(list(_normalized_queries.values()), [(normalized, query_hash)])
+
+
 class GraphQLDeferredColumnTestCase(APITestCase):
     """
     A GraphQL field backed by a custom resolver is opaque to the query optimizer, which narrows column