Add ClientErrorLogMiddleware for detailed 4xx error logging

[untidy-hair]

Hi, thank you for creating/maintaining this great library!

I've created a PR to add a logging middleware to the library for 4xx errors.
Currently when there is a 400 error, Django's logging is something very simple like this:

[WARNING] 2021-02-17 06:20:58.277 Bad Request: /graphql

I checked actual errors on client side every time this happened and sometimes it was hard to reproduce the error that had happened in the past. I knew it wouldn't be too hard to write a middleware to show more details in the logs, but it had taken me about 2 months before I actually got to write one at work. So I think it would be handy for a lot of people if we bundle one in the library.

Once you enable the middleware (please see docs/installation.rst on how), you will see more details like so:

[WARNING] 2021-02-20 18:00:50.871 Graphql Error: [{'message': 'Cannot query field "createUser" on type "Mutation".', 'locations': [{'line': 2, 'column': 3}]}]
The Query is: {'query': 'mutation {\n  createUser(userData: {\n    name: "Hallo"\n  }) {\n    user {\n      id\n      name\n    }\n  }\n}\n', 'variables': None}
[WARNING] 2021-02-17 06:20:58.277 Bad Request: /graphql

Thanks in advance :)

[zbyte64]

Should this be implemented as graphene middleware? https://docs.graphene-python.org/en/latest/execution/middleware/

[untidy-hair]

hmm, I tried implementing with graphene middleware as you suggested @zbyte64 but I cannot make it working. Could you help me with it?

logger = logging.getLogger(__name__)

class MyLogMiddleware:
    def resolve(self, next, root, info, **args):
        res = next(root, info, **args)
        if res.errors:
            # TODO: build up actual error messages. 
            logger.warning("3.141592")
        return res

def test_test(caplog):
    Reporter.objects.create(last_name="ABA")

    invalid_query = """
        query ReporterQuery {
          reporter {
            invalidAttrName 
          }
        }
    """

    schema = graphene.Schema(query=Query)
    schema.execute(invalid_query, middleware=[MyLogMiddleware()])

    # THIS FAILS, there is supposed to be one warning logged, but len() returns 0
    assert len(caplog.records) == 1

[zbyte64]

It could be that next raises an exception and res.errors gets populated further up in the stack. In PR #1122 we put the next call in a try catch block.

[untidy-hair]

I'm sorry, I haven't been able to take much time. However I read Graphene doc, too, but it doesn't seem to elaborate on how errors are handled in graphene middleware. Where should I look if I want to understand? Maybe some file suggestions if you have any?

[ulgens]

@untidy-hair I have a PR on graphql-core repo, i think it can help you how to find how errors are handled: graphql-python/graphql-core-legacy#269 (I'm aware it's not a middleware, just a suggestion 🙂 )

[untidy-hair]

@zbyte64 I was able to take some time so I looked into how graphql middleware works but I found that for some errors, middlewares will never run: https://github.com/graphql-python/graphql-core/blob/main/src/graphql/graphql.py#L166-L197.
So I think we should go with django middleware in this case? Let me know your thoughts. Thanks!