Log errors with Drupal logger

[Leksat]

After release 4.1 the module has the following error handling behavior:

https://webonyx.github.io/graphql-php/error-handling/#default-error-formatting
As of version 0.10.0, all exceptions thrown in resolvers are reported with generic message "Internal server error". This is done to avoid information leak in production environments (e.g. database connection errors, file access errors, etc).

Now the following scenario is possible:

• an exception is thrown from a resolver
• client receives "Internal server error" message
• nobody have a clue what exactly happened because the original error message is lost

Adding original error messages to Drupal log would help a lot with debugging.

Also, as a developer, I would like the log record to contain maximum debug info, e.g. GraphQL query, variables, Drupal user, etc. But I'm not sure here because GraphQL requests can potentially contain private user data.

And of course it can be a config option.

[Leksat]

As an example, here is what I already did for a project I'm working on:

my_module.module

/**
 * Implements hook_entity_type_build().
 */
function my_module_entity_type_build(&$entity_types) {
  if (isset($entity_types['graphql_server'])) {
    $entity_types['graphql_server']->setClass('Drupal\my_module\Entity\Server');
  }
}

src/Entity/Server.php

namespace Drupal\my_module\Entity;

use Drupal\Core\Utility\Error;
use Drupal\graphql\Entity\Server as ServerOriginal;
use Drupal\graphql\GraphQL\Execution\ExecutionResult as CacheableExecutionResult;
use GraphQL\Server\OperationParams;

class Server extends ServerOriginal {

  public function executeOperation(OperationParams $operation) {
    $result = parent::executeOperation($operation);

    if ($result instanceof CacheableExecutionResult && !empty($result->errors)) {
      $isPreviousLogged = FALSE;
      foreach ($result->errors as $error) {
        if ($error->getPrevious() instanceof \Throwable) {
          _drupal_log_error(Error::decodeException($error->getPrevious()));
          $isPreviousLogged = TRUE;
        }
      }
      $debug = json_encode([
        '$operation' => $operation,
        // Do not pass $result to json_encode because it has own jsonSerialize
        // method which strips some data out.
        '$result->data' => $result->data,
        '$result->errors' => $result->errors,
        '$result->extensions' => $result->extensions,
      ]);
      \Drupal::logger('my_module')->error(
        'There were errors during GraphQL execution. {previous}Debug: {debug}',
        [
          'previous' => $isPreviousLogged ? 'See previous log messages for error details. ' : '',
          'debug' => $debug,
        ]
      );
    }

    return $result;
  }

}

[Kingdutch]

I definitely think this is a good idea as I've faced similar issues. However, we should probably distinguish between server errors that are being hidden from users and GraphQL errors. Specifically the distinction I'm trying to make is errors caused by the implementation in Drupal ("server errors") and those caused by the GraphQL client ("GraphQL errors").

An example with the following schema:

type Query {
  user(id: ID!): User
}
type User {
  name: String!
}

With the following two queries:

query QueryCausingClientError {
  user(id: "some-nonexistant-user") {
   name
  }
}

query QueryCausingServerError {
  user(id: "some-existing-user-without-name") {
    name
  }
}

Here QueryCausingClientError would populate the errors array because the user with the given ID does not exist. This is an error that I can not fix by changing my server implementation, so I would not want this in my server error logs. (You can design your schema around this but it's cumbersome, uncommon and not very useful).

In contrast QueryCausingServerError returns a null value from a non-nullable field (name). This is a server error that should be fixed in some way that I would want to see in my server logs as it probably means I need to change a query or fix my schema.

The GraphQL library provides us with the ClientAware interface that may be able to help us make this distinction (the description of existing behaviour suggests that that interface is already used?)

[Leksat]

Thanks for the hint @Kingdutch!

Here is a PR: #1258