Why sys.excepthook for all (even "control flow" errors) ?

[elnygren]

Hi! I've got some testcases covering invalid mutations e.g mutating a non-existent object with an invalid UUIDv4. GraphQL and graphene handle these quite nicely (user gets a proper error message).

However, my stderr is still full of errors when I run my tests (that all pass). I did some digging with the debugger and found this line: https://github.com/graphql-python/graphql-core/blob/f8a6a8a27119f924c2fce863cca87c4219d8a12b/graphql/execution/base.py#L85

Why do we want to print everything to stderr?

manage.py test output

python manage.py test --settings=config.test_settings
Creating test database for alias 'default'...
System check identified no issues (0 silenced).
..Traceback (most recent call last):
  File "/Users/elnygren/Work/sumpli/sumpli-core/ENV/lib/python3.6/site-packages/graphql/execution/executor.py", line 215, in complete_value_catching_error
    exe_context, return_type, field_asts, info, result)
  File "/Users/elnygren/Work/sumpli/sumpli-core/ENV/lib/python3.6/site-packages/graphql/execution/executor.py", line 268, in complete_value
    raise GraphQLLocatedError(field_asts, original_error=result)
graphql.error.located_error.GraphQLLocatedError: No Business matches the given query.
.Traceback (most recent call last):
  File "/Users/elnygren/Work/sumpli/sumpli-core/ENV/lib/python3.6/site-packages/graphql/execution/executor.py", line 215, in complete_value_catching_error
    exe_context, return_type, field_asts, info, result)
  File "/Users/elnygren/Work/sumpli/sumpli-core/ENV/lib/python3.6/site-packages/graphql/execution/executor.py", line 268, in complete_value
    raise GraphQLLocatedError(field_asts, original_error=result)
graphql.error.located_error.GraphQLLocatedError: 'foo-bar-xyz-abc' is not a valid UUID.
.....................................

Note that:

No Business matches the given query.

and

'foo-bar-xyz-abc' is not a valid UUID.

are the messages shown to the users.

Code

class LikeABusiness(graphene.Mutation):
    """Mutation for liking/following a Business."""
    class Arguments:
        """Arguments of the Mutation"""
        uuid = graphene.String(required=True)

    # output
    ok = graphene.Boolean()

    def mutate(self, info, uuid, *args, **kwargs):
        """Perform the data mutation."""
        try:
            # raises the "No Business matches the given query." message due to 404
            return LikeABusiness(
                ok=get_object_or_404(Business, uuid=uuid).like(info.context.user)
            )
        except ValidationError as e:
            # passes along the "'foo-bar-xyz-abc' is not a valid UUID." message
            raise Exception(e.messages[0])

[janosroden]

I'm new in python, but I think this is the cause of the "Press Enter to continue" message during debugging such a test.

[zyguan]

That's annoying! Can we make the error reporting configurable? eg. add an additional callback arg to ExecutionContext and execute or just allow us to pass the custom context class to the execute function.

[mariogarcia]

I've found a possible solution, at least for middlewares:

I've created an authentication middleware and I had the same problem. It was very annoying getting stacktraces every time a user failed to authenticate.

Looking into this I realized that tests regarding middlewares were using promises, so I thought what would happen if I returned Promise.reject(GraphQLError('message')) from my middleware instead or raising the error.

It turned out to be the solution, it shows the graphql error to the user and it's logged as a single error line by the application logging system. No more stacktraces everywhere.

I hope this helps

[elnygren]

@mariogarcia after your trick my

python manage.py test --settings=config.test_settings
Creating test database for alias 'default'...
System check identified no issues (0 silenced).
..Traceback (most recent call last):
  File "/Users/elnygren/Work/sumpli/sumpli-core/ENV/lib/python3.6/site-packages/graphql/execution/executor.py", line 215, in complete_value_catching_error
    exe_context, return_type, field_asts, info, result)
  File "/Users/elnygren/Work/sumpli/sumpli-core/ENV/lib/python3.6/site-packages/graphql/execution/executor.py", line 268, in complete_value
    raise GraphQLLocatedError(field_asts, original_error=result)
graphql.error.located_error.GraphQLLocatedError: No Business matches the given query.
.Traceback (most recent call last):
  File "/Users/elnygren/Work/sumpli/sumpli-core/ENV/lib/python3.6/site-packages/graphql/execution/executor.py", line 215, in complete_value_catching_error
    exe_context, return_type, field_asts, info, result)
  File "/Users/elnygren/Work/sumpli/sumpli-core/ENV/lib/python3.6/site-packages/graphql/execution/executor.py", line 268, in complete_value
    raise GraphQLLocatedError(field_asts, original_error=result)
graphql.error.located_error.GraphQLLocatedError: 'foo-bar-xyz-abc' is not a valid UUID.
.....................................

turned into

python manage.py test --settings=config.test_settings
Creating test database for alias 'default'...
System check identified no issues (0 silenced).
..graphql.error.located_error.GraphQLLocatedError: No Brand matches the given query.
.graphql.error.located_error.GraphQLLocatedError: 'foo-bar-xyz-abc' is not a valid UUID.
........................................

So a little less verbose but still unnecessary printing of errors somewhere....

Code:

    except ValidationError as e:
        return Promise.reject(GraphQLError(e.messages[0]))

[mariogarcia]

Well in my case I think is still desirable to have a minimum traceability of authentication errors.

But yeah, I think you're right, maybe there should be a specific type of error that graphql-core could propagate without being verbose along the way. Or maybe a flag in the GraphQLError type:

Special type:

Promise.reject(GraphQLUserError('message'))

or flag:

Promise.reject(GraphQLError(message='message', log=False))

[zyguan]

@elnygren If you do not wanna see any annoying output, you can actually overwrite the sys.excepthook, eg. put the following code to your setup function.

sys.excepthook = lambda *_: None

However it's not a good idea to ignore all exceptions. So you may use an custom exception to specify which you want to ignore.

class AppWarning(Exception):
    pass


def app_excepthook(t, e, tb):
    if isinstance(e, GraphQLLocatedError) and \
            isinstance(e.original_error, AppWarning):
        return  # or put a warning msg if you want
    else:
        logging.error('Uncaught error: %s', e, exc_info=(t, e, tb))

sys.excepthook = app_excepthook

In my humble opinion, you'd better set stack attribute to all errors caught by you logic code (and then reject them) so that the important traceback info won't be discard by GraphQLLocatedError. eg:

try:
    # your logic code here
except Exception as e:
    if not hasattr(e, 'stack'):
        _, _, tb = sys.exc_info()
        setattr(e, 'stack', tb)
    return Promise.reject(e)

[CaselIT]

I think that the best option would be to use the logging library to log the error instead of sys.excepthook, so the user of the library has full control on what should be reported.

[CaselIT]

I've added a PR to close this issue.

[charettes]

Thanks for the PR @CaselIT, I also agreed that logger.exception is a way better option that sys.excepthook to propagate these errors.

[tlinhart]

@CaselIT @charettes Guys, how does this solve the original problem? Say I want to be able to selectively control which exceptions should only result in error messages in the output and which should also be logged (possibly with stack trace) for later debugging. The former could be a case for business logic errors in resolvers (e.g. authentication/authorization errors). The later could stem from uncaught exceptions or exceptions deliberately left to propagate (e.g. failed database reads or external API calls).

Is there a way to control this behaviour? sys.excepthook at least provided a way to solve this but I'm not sure how to do it when exceptions are logged.

[charettes]

@tlinhart isn't this something you can achieve with logging filters and handlers?