Errors get swallowed up

[jonom]

Hi there,

I was trying to add Sentry error tracking to a project but found that errors thrown during a GraphQL request get swallowed up. It seems that graphql-php catches the error first, but even if I was to re-throw it somehow, this module would catch it as well.

Sorry if I'm missing something obvious here but I'm wondering how to log errors properly.

I found that if I hacked QueryHandler::query() I could manually report an error, so I'm wondering if some logging code should be added here, or perhaps an extension point?

/**
    * @param GraphQLSchema $schema
    * @param string|DocumentNode $query
    * @param array|null $vars
    * @return array
    */
public function query(GraphQLSchema $schema, $query, ?array $vars = []): array
{
    $executionResult = $this->queryAndReturnResult($schema, $query, $vars);

    // Manual Sentry error logging
    try {
        if (isset($executionResult->errors[0])) {
            if ($executionResult->errors[0]->getPrevious()) {
                // Error caused by the app-resolver
                throw $executionResult->errors[0]->getPrevious();
            } else {
                // GraphQL-specific error
                throw $executionResult->errors[0];
            }
        }
    } catch (\Exception $e) {
        $logger = Injector::inst()->createWithArgs(Logger::class, ['error-log'])
            ->pushHandler(\PhpTek\Sentry\Handler\SentryHandler::create());
        $logger->error($e, $e->getTrace());
    }

    // Already in array form
    if (is_array($executionResult)) {
        return $executionResult;
    }
    return $this->serialiseResult($executionResult);
}

[michalkleiner]

We can certainly add an extension point, e.g. updateQueryExecutionResult($executionResult), but it might be worth looking at other options as well to know if we're not missing something.

[jonom]

I've been trying to wrap my head around this and have found that I was partially chasing a red herring - in dev mode triggered errors are handled by SilverStripe\GraphQL\QueryHandler\DevErrorHandler which returns a nice json response but prevents regular Silverstripe error handling/logging.

In live mode that doesn't happen, but one drawback is that the client receives an HTML formatted friendly error message response. It might be nice if the default behaviour was to allow normal Silverstripe error handling/logging, but use a formatter appropriate for a GraphQL response. In practice though I don't know if that would make a difference for the client, since it would get a 500 response code?

In either mode I found that if I throw an ErrorException in a resolver, I get a 200 JSON response with error details, but nothing gets logged. I tried using a custom error handler function with SilverStripe\GraphQL\QueryHandler::setErrorHandler() but that only works for triggered errors, not thrown exceptions. I also tried modifying SilverStripe\GraphQL\QueryHandler::queryAndReturnResult() to add a ->setErrorsHandler() call to GraphQL::executeQuery() as indicated here, but it doesn't fire. The docs seem to indicate that caught warnings and errors should be handled with trigger_error but that doesn't happen for me.

Anyway... as per the example code above, it is possible to get a hold of the original exception thrown in a resolver within QueryHandler::query(), but after that it's gone, because serialiseResult will format the errors ready to go in to a response and strip out any stack trace info (the useful parts at least). Which is what you want - but it means we can't use an afterware to capture and log error details.

The change below seems to accomplish what I want and allow exceptions to be logged. I could achieve that if we add an extension point, or perhaps it would be worth adding to the module? I'm not well versed on best practices around throwing exceptions in PHP and whether the below would suit all users, but I do feel that there's a hole in GraphQL error logging capabilities currently.

public function query(GraphQLSchema $schema, $query, ?array $vars = []): array
{
    $executionResult = $this->queryAndReturnResult($schema, $query, $vars);

    // START -- Log exceptions
    $errors = $executionResult->errors ?? [];
    foreach ($errors as $error) {
        $e = $error->getPrevious();
        // Error caused by the app-resolver
        if ($e) {
            $level = 'error';
            if ($e instanceof \ErrorException) {
                $severity = $e->getSeverity();
                if (in_array($severity, [E_WARNING, E_USER_WARNING])) {
                    $level = 'warning';
                } else if (in_array($severity, [E_NOTICE, E_USER_NOTICE])) {
                    $level = 'notice';
                }
            }
            Injector::inst()->get(LoggerInterface::class)->$level($e->getMessage(), [
                'file' => $e->getFile(),
                'line' => $e->getLine(),
            ]);
        }
    }
    // END -- Log exceptions

    // Already in array form
    if (is_array($executionResult)) {
        return $executionResult;
    }
    return $this->serialiseResult($executionResult);
}

[kinglozzer]

Had a quick look at this today because I think we’re also missing the use case of partial data/partial error. I.e. in the response, both data and errors are populated and the client can then decide whether to error, or render partial data (Apollo defaults to discarding partial data but can be configured).

Currently, if an error is encountered during dev it replaces the data entirely. And if the site is in live mode, they’re typically silently swallowed (as described in this ticket).