How to see graphene-django DEBUG logs

Question

I'm having trouble viewing DEBUG level logs with Graphene and Django. I've set the following in settings.py:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
        },
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
            'level': 'DEBUG'
        },
        'django.request': {
            'handlers': ['console'],
            'level': 'DEBUG'
        },
    },
}

However, when I try to look at the logs of my Django server all I see is:

 ❯❯❯ kubectl logs -f server-6b65f48895-bmp6w server
Operations to perform:
  Apply all migrations: admin, auth, contenttypes, django_celery_beat, django_celery_results, server, sessions, social_django
Running migrations:
  No migrations to apply.
Performing system checks...

System check identified no issues (0 silenced).
October 08, 2018 - 23:59:00
Django version 2.0.6, using settings 'backend.settings'
Starting development server at http://0.0.0.0:8000/
Quit the server with CONTROL-C.
"POST /graphql HTTP/1.1" 400 113
"POST /graphql HTTP/1.1" 400 113
"POST /graphql HTTP/1.1" 400 113
"POST /graphql HTTP/1.1" 400 113
"POST /graphql HTTP/1.1" 400 113
"POST /graphql HTTP/1.1" 400 113
"POST /graphql HTTP/1.1" 400 113
"POST /graphql HTTP/1.1" 400 113
"POST /graphql HTTP/1.1" 400 113
"POST /graphql HTTP/1.1" 400 113

How can I view DEBUG level logs to figure out why my server is constantly serving 400s?

I have the Django DEBUG environment variable unset. I'm trying to debug a production issue.

Answer 1

I was messed with the same question a while ago and came to the workaround solution:

from promise import is_thenable


class DebugMiddleware(object):
    def on_error(self, error):
        print(error)

    def resolve(self, next, root, info, **args):
        result = next(root, info, **args)
        if is_thenable(result):
            result.catch(self.on_error)

        return result

And tell graphene to use it as middleware:

GRAPHENE = {
    ...
    'MIDDLEWARE': [
        'path.to.containing.module.DebugMiddleware',
        ...
    ]
}

Here you get access to an error trowed on resolve.

Initial problem (no module logging) may be caused by disabled graphql logger, but my explorations in this direction didn't have any results :(

Answer 2

Here's a quick middleware I threw together to capture graphql query 400 errors.

In settings.py

MIDDLEWARE = [
    "path_to_file_below.GraphqlErrorLogMiddleware",
    ...
]

# Some basic logging from the Django Documentation
LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "handlers": {"console": {"class": "logging.StreamHandler"}},
    "root": {"handlers": ["console"], "level": "DEBUG"},
}

class GraphqlErrorLogMiddleware(object):
    """
    Logs errors for invalid graphql queries
    """

    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
                and response.status_code != 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']}",
                        response=response,
                        level="error",
                    )
        except Exception as e:
            logging.debug(f"Error logging Graphql Error: {e}")

        return response

Answer 3

Based on @donnyy answer I came up with the following implementation

from promise import is_thenable
from functools import partial
import logging
import sys
import json
logging.basicConfig(stream=sys.stdout, level=logging.DEBUG)

class DebugMiddleware(object):
    def on_error(self, error ,info):
        log_request_body(info)

    def resolve(self, next, root, info, **args):

        result = next(root, info, **args)
        if is_thenable(result):
            result.catch(partial(self.on_error, info=info))
        return result


def log_request_body(info):
    body = info.context._body.decode('utf-8')
    try:
        json_body = json.loads(body)
        logging.error(' User: %s \n Action: %s \n Variables: %s \n Body: %s',
                      info.context.user,
                      json_body['operationName'],
                      json_body['variables'],
                      json_body['query'])
    except:
        logging.error(body)