Skip to content

feat(server): log unsafe errors #1258

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 10 commits into from
Feb 10, 2022
Merged

feat(server): log unsafe errors #1258

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
10 commits
Select commit Hold shift + click to select a range
cf5a7a1
feat(server): log unsafe errors
Leksat Jan 18, 2022
0aed48b
chore: fix phpstan/phpcs errors
Leksat Jan 18, 2022
5139962
chore: redo the logic as suggested by @Kingdutch
Leksat Feb 9, 2022
9ee8313
chore: rename the method
Leksat Feb 9, 2022
5508a41
chore: log everything in one message
Leksat Feb 9, 2022
063ba6a
chore: better variable name
Leksat Feb 9, 2022
db10276
Merge branch '8.x-4.x' into log-unsafe-errors
klausi Feb 9, 2022
bc583de
chore: move logging to Executor
Leksat Feb 10, 2022
7f830b1
test: add logger tests
Leksat Feb 10, 2022
93b7ec8
fix: fix phpcs error
Leksat Feb 10, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
53 changes: 53 additions & 0 deletions src/GraphQL/Execution/Executor.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,15 +6,18 @@
use Drupal\Core\Cache\CacheableMetadata;
use Drupal\Core\Cache\CacheBackendInterface;
use Drupal\Core\Cache\Context\CacheContextsManager;
use Drupal\Core\Utility\Error as ErrorUtil;
use Drupal\graphql\Event\OperationEvent;
use Drupal\graphql\GraphQL\Execution\ExecutionResult as CacheableExecutionResult;
use Drupal\graphql\GraphQL\Utility\DocumentSerializer;
use GraphQL\Error\ClientAware;
use GraphQL\Executor\ExecutionResult;
use GraphQL\Executor\ExecutorImplementation;
use GraphQL\Executor\Promise\Promise;
use GraphQL\Executor\Promise\PromiseAdapter;
use GraphQL\Executor\ReferenceExecutor;
use GraphQL\Language\AST\DocumentNode;
use GraphQL\Server\OperationParams;
use GraphQL\Type\Schema;
use GraphQL\Utils\AST;
use Symfony\Component\DependencyInjection\ContainerInterface;
Expand Down Expand Up @@ -280,10 +283,60 @@ protected function doExecuteUncached() {
$event = new OperationEvent($this->context, $result);
$this->dispatcher->dispatch(OperationEvent::GRAPHQL_OPERATION_AFTER, $event);

$this->logUnsafeErrors($this->context->getOperation(), $result);

return $result;
});
}

/**
* Logs unsafe errors if any.
*
* @param \GraphQL\Server\OperationParams $operation
* @param \Drupal\graphql\GraphQL\Execution\ExecutionResult $result
*/
protected function logUnsafeErrors(OperationParams $operation, ExecutionResult $result): void {
$hasUnsafeErrors = FALSE;
$previousErrors = [];

foreach ($result->errors as $index => $error) {
// Don't log errors intended for clients, only log those that
// a client would not be able to solve, they'd require work from
// a server developer.
if ($error instanceof ClientAware && $error->isClientSafe()) {
continue;
}

$hasUnsafeErrors = TRUE;
// Log the error that cause the error we caught. This makes the error
// logs more useful because GraphQL usually wraps the original error.
if ($error->getPrevious() instanceof \Throwable) {
$previousErrors[] = strtr(
"For error #@index: %type: @message in %function (line %line of %file)\n@backtrace_string.",
ErrorUtil::decodeException($error->getPrevious()) + ['@index' => $index]
);
}
}

if ($hasUnsafeErrors) {
\Drupal::logger('graphql')->error(
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We should inject the logger, but does not matter much in this class. Can be done in a follow-up.

"There were errors during a GraphQL execution.\nOperation details:\n<pre>\n{details}\n</pre>\nPrevious errors:\n<pre>\n{previous}\n</pre>",
[
'details' => json_encode([
'$operation' => $operation,
// Do not pass $result to json_encode because it implements
// JsonSerializable and strips some data out during the
// serialization.
'$result->data' => $result->data,
'$result->errors' => $result->errors,
'$result->extensions' => $result->extensions,
], JSON_PRETTY_PRINT),
'previous' => implode('\n\n', $previousErrors),
]
);
}
}

/**
* Calculates the cache prefix from context for the current query.
*
Expand Down
174 changes: 174 additions & 0 deletions tests/src/Kernel/Framework/LoggerTest.php
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,174 @@
<?php

namespace Drupal\Tests\graphql\Kernel\Framework;

use Drupal\Core\Logger\RfcLoggerTrait;
use Drupal\Tests\graphql\Kernel\GraphQLTestBase;
use Psr\Log\LoggerInterface;

/**
* Test error logging.
*
* @group graphql
*/
class LoggerTest extends GraphQLTestBase implements LoggerInterface {

use RfcLoggerTrait;

/**
* Loggers calls.
*
* @var array
*/
protected $loggerCalls = [];

/**
* {@inheritdoc}
*/
protected function setUp(): void {
parent::setUp();

$schema = <<<GQL
schema {
query: Query
}
type Query {
resolvesToNull: String!
throwsException: String!
takesIntArgument(id: Int!): String
}
GQL;

$this->setUpSchema($schema);

$this->mockResolver('Query', 'resolvesToNull', NULL);
$this->mockResolver('Query', 'throwsException', function () {
throw new \Exception('BOOM!');
});
$this->mockResolver('Query', 'takesIntArgument');

$this->container->get('logger.factory')->addLogger($this);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice trick, this is really convenient. I need to remember that.

}

/**
* {@inheritdoc}
*/
public function log($level, $message, array $context = []) {
$this->loggerCalls[] = [
'level' => $level,
'message' => $message,
'context' => $context,
];
}

/**
* Test if invariant violation errors are logged.
*/
public function testInvariantViolationError(): void {
$result = $this->query('query { resolvesToNull }');
$this->assertSame(200, $result->getStatusCode());
// Client should not see the actual error.
$this->assertSame([
'errors' => [
[
'message' => 'Internal server error',
'extensions' => [
'category' => 'internal',
],
'locations' => [
[
'line' => 1,
'column' => 9,
],
],
'path' => [
'resolvesToNull',
],
],
],
], json_decode($result->getContent(), TRUE));
// The error should be logged.
$this->assertCount(1, $this->loggerCalls);
$loggerCall = reset($this->loggerCalls);
$details = json_decode($loggerCall['context']['details'], TRUE);
$this->assertSame($details['$operation']['query'], 'query { resolvesToNull }');
$this->assertSame($details['$operation']['variables'], []);
$this->assertCount(1, $details['$result->errors']);
$this->assertSame(
$details['$result->errors'][0]['message'],
'Cannot return null for non-nullable field "Query.resolvesToNull".'
);
$this->assertStringContainsString(
'For error #0: GraphQL\Error\InvariantViolation: Cannot return null for non-nullable field "Query.resolvesToNull".',
$loggerCall['context']['previous']
);
}

/**
* Test if exceptions thrown from resolvers are logged.
*/
public function testException(): void {
$result = $this->query('query { throwsException }');
$this->assertSame(200, $result->getStatusCode());
// Client should not see the actual error.
$this->assertSame([
'errors' => [
[
'message' => 'Internal server error',
'extensions' => [
'category' => 'internal',
],
'locations' => [
[
'line' => 1,
'column' => 9,
],
],
'path' => [
'throwsException',
],
],
],
], json_decode($result->getContent(), TRUE));
// The error should be logged.
$this->assertCount(1, $this->loggerCalls);
$loggerCall = reset($this->loggerCalls);
$details = json_decode($loggerCall['context']['details'], TRUE);
$this->assertSame($details['$operation']['query'], 'query { throwsException }');
$this->assertSame($details['$operation']['variables'], []);
$this->assertCount(1, $details['$result->errors']);
$this->assertSame($details['$result->errors'][0]['message'], 'BOOM!');
$this->assertStringContainsString(
'For error #0: Exception: BOOM!',
$loggerCall['context']['previous']
);
}

/**
* Test if client error are not logged.
*/
public function testClientError(): void {
$result = $this->query('query { takesIntArgument(id: "boom") }');
$this->assertSame(200, $result->getStatusCode());
// The error should be reported back to client.
$this->assertSame([
'errors' => [
0 => [
'message' => 'Field "takesIntArgument" argument "id" requires type Int!, found "boom".',
'extensions' => [
'category' => 'graphql',
],
'locations' => [
0 => [
'line' => 1,
'column' => 30,
],
],
],
],
], json_decode($result->getContent(), TRUE));
// The error should not be logged.
$this->assertCount(0, $this->loggerCalls);
}

}
1 change: 1 addition & 0 deletions tests/src/Kernel/GraphQLTestBase.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -70,6 +70,7 @@ protected function setUp(): void {
$this->installEntitySchema('graphql_server');
$this->installEntitySchema('configurable_language');
$this->installConfig(['language']);
$this->installEntitySchema('menu_link_content');
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't even want to know why we need this :-D But totally fine, thanks!

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

On the query run there was an error logged. Something like "DB error: menu_link_content table does not exist". I also did not want to know why it happens 😅 So I just installed menu_link_content schema.

Copy link
Contributor

@Kingdutch Kingdutch Feb 11, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we know in what test this was? This could indicate a hidden dependency that I don't think should exist. So in theory this could even be flagging a breaking change.

(It's also not a module I'd expect should be added for all tests, so I'm not sure if GraphQLTestBase is the way to go).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It was happening in the new test I created.


$this->setUpCurrentUser([], $this->userPermissions());

Expand Down