From 54bb9371af36b7cc31c04bfe4d3cf55c612787a2 Mon Sep 17 00:00:00 2001
From: Yukio Mizuta <untidyhair@gmail.com>
Date: Sat, 20 Feb 2021 12:26:20 -0500
Subject: [PATCH] Add ClientErrorLogMiddleware for detailed logging

---
 docs/installation.rst                     |  18 ++++
 graphene_django/middlewares.py            |  39 ++++++++
 graphene_django/tests/test_middlewares.py | 107 ++++++++++++++++++++++
 3 files changed, 164 insertions(+)
 create mode 100644 graphene_django/middlewares.py
 create mode 100644 graphene_django/tests/test_middlewares.py

diff --git a/docs/installation.rst b/docs/installation.rst
index 88b7922..2529e3a 100644
--- a/docs/installation.rst
+++ b/docs/installation.rst
@@ -91,3 +91,21 @@ decorator:
         # ...
         path("graphql", csrf_exempt(GraphQLView.as_view(graphiql=True))),
     ]
+
+Logging Errors
+--------------
+
+By default, when there is a GraphQL error because of client inputs , Django logs a very simple message
+with 4xx HTTP status code. If you would like to see more details, you can enable
+``ClientErrorLogMiddleware`` as follows:
+
+.. code:: python
+
+    # settings.py
+
+    MIDDLEWARE = [
+        "graphene_django.middlewares.ClientErrorLogMiddleware",
+        # ...
+    ]
+
+This middleware works when your endpoint is ``/graphql``.
diff --git a/graphene_django/middlewares.py b/graphene_django/middlewares.py
new file mode 100644
index 0000000..f914bf6
--- /dev/null
+++ b/graphene_django/middlewares.py
@@ -0,0 +1,39 @@
+import json
+import logging
+
+from django.utils.log import log_response
+
+logger = logging.getLogger("django.graphene")
+
+
+class ClientErrorLogMiddleware:
+    """
+    Logs graphql requests 4xx errors. (Except 401, 403)
+    """
+
+    def __init__(self, get_response):
+        self.get_response = get_response
+
+    def __call__(self, request):
+        response = self.get_response(request)
+
+        try:
+            if (
+                400 <= response.status_code < 500
+                and response.status_code not in (401, 403)
+                and "graphql" in request.path.lower()
+            ):
+                response_json = json.loads(response.content)
+
+                if "errors" in response_json:
+                    log_response(
+                        message=(
+                            f"Graphql Error: {response_json['errors']}\n"
+                            f"The Query is: {json.loads(request.body)}"
+                        ),
+                        response=response,
+                    )
+        except Exception:
+            logger.error(f"Error logging graphql error.", exc_info=True)
+
+        return response
diff --git a/graphene_django/tests/test_middlewares.py b/graphene_django/tests/test_middlewares.py
new file mode 100644
index 0000000..fb254a8
--- /dev/null
+++ b/graphene_django/tests/test_middlewares.py
@@ -0,0 +1,107 @@
+import json
+import logging
+import graphene
+import mock
+from django.http.response import HttpResponse
+from django.test import RequestFactory
+from graphene.test import Client
+
+from .models import Reporter
+from .. import DjangoObjectType
+from ..middlewares import ClientErrorLogMiddleware
+
+
+class ReporterType(DjangoObjectType):
+    class Meta:
+        model = Reporter
+        fields = "__all__"
+
+
+class Query(graphene.ObjectType):
+    reporter = graphene.Field(ReporterType)
+
+    def resolve_reporter(self, info, **args):
+        return Reporter.objects.first()
+
+
+def test_should_log_error(caplog):
+    Reporter.objects.create(last_name="ABA")
+
+    invalid_query = """
+        query ReporterQuery {
+          reporter {
+            invalidAttrName 
+          }
+        }
+    """
+
+    schema = graphene.Schema(query=Query)
+    client = Client(schema)
+    response = client.execute(invalid_query)
+
+    factory = RequestFactory()
+    request = factory.post(
+        "/graphql", data=json.dumps(invalid_query), content_type="application/json"
+    )
+
+    http_res = HttpResponse(json.dumps(response).encode(), status=400)
+
+    get_response = mock.MagicMock()
+    get_response.return_value = http_res
+
+    middleware = ClientErrorLogMiddleware(get_response)
+    middleware(request)
+
+    assert len(caplog.records) == 1
+    assert caplog.records[0] != "WARNING"
+    assert str(response["errors"]) in caplog.text
+    assert invalid_query in caplog.text
+
+
+def test_should_not_log_success(caplog):
+    Reporter.objects.create(last_name="ABA")
+
+    valid_query = """
+        query ReporterQuery {
+          reporter {
+            lastName
+          }
+        }
+    """
+
+    schema = graphene.Schema(query=Query)
+    client = Client(schema)
+    response = client.execute(valid_query)
+
+    factory = RequestFactory()
+    request = factory.post(
+        "/graphql", data=json.dumps(valid_query), content_type="application/json"
+    )
+
+    http_res = HttpResponse(json.dumps(response).encode(), status=200)
+
+    get_response = mock.MagicMock()
+    get_response.return_value = http_res
+
+    middleware = ClientErrorLogMiddleware(get_response)
+    middleware(request)
+
+    assert len(caplog.records) == 0
+
+
+def test_should_not_log_non_graphql_error(caplog):
+    factory = RequestFactory()
+    request = factory.post(
+        "/users", data=json.dumps({"name": "Mario"}), content_type="application/json"
+    )
+    http_res = HttpResponse(
+        json.dumps({"errors": ["Got to be Luigi"]}).encode(), status=400
+    )
+
+    get_response = mock.MagicMock()
+    get_response.return_value = http_res
+
+    middleware = ClientErrorLogMiddleware(get_response)
+    middleware(request)
+
+    assert len(caplog.records) == 0