AsyncioExecutor produces hard to debug errors

[BenoitZugmeyer]

When an async resolver is raising an exception, this exception is not logged and its stack in lost and never printed. The only "report" is the error carried by the ExecutionResult but we can only access its type and message, not the actual stack trace.

This is different for sync resolvers (even when using the AsyncioExecutor): the exception is printed by graphql.execution.executor resolve_or_error.

Below is an example to illustrate the issue:

from graphql.execution.executors.asyncio import AsyncioExecutor
from graphql import GraphQLObjectType, GraphQLField, GraphQLString, GraphQLSchema, graphql

def resolve_hello(root, args, context, info):
    raise Exception("wololo")

async def resolve_hello_async(root, args, context, info):
    raise Exception("wololo")

QueryType = GraphQLObjectType("Query", fields={
    "hello": GraphQLField(GraphQLString, resolver=resolve_hello),
    "helloAsync": GraphQLField(GraphQLString, resolver=resolve_hello_async),
})

schema = GraphQLSchema(query=QueryType)

print("Sync execution")

result = graphql(schema, '{ hello }', executor=AsyncioExecutor())
# This will log something like:
#
# An error occurred while resolving field Query.hello
# Traceback (most recent call last):
#   File ".../site-packages/graphql/execution/executor.py", line 200, in resolve_or_error
#     return executor.execute(resolve_fn, source, args, context, info)
#   File ".../site-packages/graphql/execution/executors/asyncio.py", line 50, in execute
#     result = fn(*args, **kwargs)
#   File "test.py", line 11, in resolve_hello
#     raise Exception("wololo")
# Exception: wololo

# As a side note, the produced error have a correct stack trace:
print(result.errors[0].stack) # <traceback object at 0x123456789>

print("=" * 10)
print("Async execution")

async_result = graphql(schema, '{ helloAsync }', executor=AsyncioExecutor())
# While producing the same result, it won't log anything, and good luck to know where
# the error comes from.

# This error has None as a stack trace:
print(async_result.errors[0].stack) # None

I am a beginner with python async stuff so I won't send a PR, but as a temporary solution I am replacing the AsyncioExecutor execute method with something like that:

    def execute(self, fn, *args, **kwargs):
        result = fn(*args, **kwargs)
        if isinstance(result, Future) or iscoroutine(result):
            async def hop():
                try:
                    awaited_result = await result
                except Exception as e:
                    logger.exception("Exception in %s", fn)
                    raise
                return awaited_result
            future = ensure_future(hop(), loop=self.loop)
            # future = ensure_future(result, loop=self.loop)
            self.futures.append(future)
            return Promise.resolve(future)
        return result

EDIT: I am using graphene 1.4 and graphql 1.1

[gdw2]

Same issue here

[achimnol]

In graphql-core 2.0.dev20170801051721, you can do:

# (your sample code pasted here)
import traceback
ex = async_result.errors[0].original_error
traceback.print_exception(type(ex), ex, ex.__traceback__)

Traceback (most recent call last):
  File "test_gql_ex.py", line 8, in resolve_hello_async
    raise Exception("wololo")
Exception: wololo

[achimnol]

And in general, when writing asyncio-based programs we need explicit exception handling at the top stack frame of each asyncio Task (for all unexpected errors). Without explicit handling, the errors are only reported when the task is deleted from the memory, which usually happens when the event loop shuts down.

[achimnol]

Hm... I've also found that the code here

        if hasattr(original_error, 'stack'):
            stack = original_error.stack

should check original_error.__traceback__ instead, because original_error may be just an arbitrary Python exceptions which might not have stack property (which is the convention in graphql-core). But __traecback__ is only available in Python 3, so we need some other way to do the same for Python 2.

[BenoitZugmeyer]

For those who are looking for a quick solution, this is how I resolved it in graphql 1.1:

import logging
from graphql.execution.executors.asyncio import AsyncioExecutor
from promise import Promise

logger = logging.getLogger(__name__)

class LoggingAsyncioExecutor(AsyncioExecutor):
    def execute(self, fn, *args, **kwargs):
        result = super().execute(fn, *args, **kwargs)
        if isinstance(result, Promise):
            def log_exception(ex):
                logger.error(
                    "Unhandled error in %s:\n%s",
                    fn,
                    "".join(traceback.format_exception(type(ex), ex, ex.__traceback__))
                )
                raise ex
            result = result.catch(log_exception)
        return result

# Then use LoggingAsyncioExecutor in place of AsyncioExecutor
# Example with flask_graphql:
app.add_url_rule('/graphql', view_func=GraphQLView.as_view(
    'graphql',
    schema=schema,
    graphiql=True,
    executor=LoggingAsyncioExecutor(loop=loop)
))

[dpnova]

Legend, this works wonderfully for now!