Skip to content

Commit e211199

Browse files
LeksatLeksat
authored
feat(server): Log unsafe server errors for better error tracing (#1258)
1 parent eaa4f86 commit e211199

3 files changed

Lines changed: 228 additions & 0 deletions

File tree

‎src/GraphQL/Execution/Executor.php‎

Lines changed: 53 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,15 +6,18 @@
66
use Drupal\Core\Cache\CacheableMetadata;
77
use Drupal\Core\Cache\CacheBackendInterface;
88
use Drupal\Core\Cache\Context\CacheContextsManager;
9+
use Drupal\Core\Utility\Error as ErrorUtil;
910
use Drupal\graphql\Event\OperationEvent;
1011
use Drupal\graphql\GraphQL\Execution\ExecutionResult as CacheableExecutionResult;
1112
use Drupal\graphql\GraphQL\Utility\DocumentSerializer;
13+
use GraphQL\Error\ClientAware;
1214
use GraphQL\Executor\ExecutionResult;
1315
use GraphQL\Executor\ExecutorImplementation;
1416
use GraphQL\Executor\Promise\Promise;
1517
use GraphQL\Executor\Promise\PromiseAdapter;
1618
use GraphQL\Executor\ReferenceExecutor;
1719
use GraphQL\Language\AST\DocumentNode;
20+
use GraphQL\Server\OperationParams;
1821
use GraphQL\Type\Schema;
1922
use GraphQL\Utils\AST;
2023
use Symfony\Component\DependencyInjection\ContainerInterface;
@@ -280,10 +283,60 @@ protected function doExecuteUncached() {
280283
$event = new OperationEvent($this->context, $result);
281284
$this->dispatcher->dispatch(OperationEvent::GRAPHQL_OPERATION_AFTER, $event);
282285

286+
$this->logUnsafeErrors($this->context->getOperation(), $result);
287+
283288
return $result;
284289
});
285290
}
286291

292+
/**
293+
* Logs unsafe errors if any.
294+
*
295+
* @param \GraphQL\Server\OperationParams $operation
296+
* @param \Drupal\graphql\GraphQL\Execution\ExecutionResult $result
297+
*/
298+
protected function logUnsafeErrors(OperationParams $operation, ExecutionResult $result): void {
299+
$hasUnsafeErrors = FALSE;
300+
$previousErrors = [];
301+
302+
foreach ($result->errors as $index => $error) {
303+
// Don't log errors intended for clients, only log those that
304+
// a client would not be able to solve, they'd require work from
305+
// a server developer.
306+
if ($error instanceof ClientAware && $error->isClientSafe()) {
307+
continue;
308+
}
309+
310+
$hasUnsafeErrors = TRUE;
311+
// Log the error that cause the error we caught. This makes the error
312+
// logs more useful because GraphQL usually wraps the original error.
313+
if ($error->getPrevious() instanceof \Throwable) {
314+
$previousErrors[] = strtr(
315+
"For error #@index: %type: @message in %function (line %line of %file)\n@backtrace_string.",
316+
ErrorUtil::decodeException($error->getPrevious()) + ['@index' => $index]
317+
);
318+
}
319+
}
320+
321+
if ($hasUnsafeErrors) {
322+
\Drupal::logger('graphql')->error(
323+
"There were errors during a GraphQL execution.\nOperation details:\n<pre>\n{details}\n</pre>\nPrevious errors:\n<pre>\n{previous}\n</pre>",
324+
[
325+
'details' => json_encode([
326+
'$operation' => $operation,
327+
// Do not pass $result to json_encode because it implements
328+
// JsonSerializable and strips some data out during the
329+
// serialization.
330+
'$result->data' => $result->data,
331+
'$result->errors' => $result->errors,
332+
'$result->extensions' => $result->extensions,
333+
], JSON_PRETTY_PRINT),
334+
'previous' => implode('\n\n', $previousErrors),
335+
]
336+
);
337+
}
338+
}
339+
287340
/**
288341
* Calculates the cache prefix from context for the current query.
289342
*

‎tests/src/Kernel/Framework/LoggerTest.php‎

Lines changed: 174 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,174 @@
1+
<?php
2+
3+
namespace Drupal\Tests\graphql\Kernel\Framework;
4+
5+
use Drupal\Core\Logger\RfcLoggerTrait;
6+
use Drupal\Tests\graphql\Kernel\GraphQLTestBase;
7+
use Psr\Log\LoggerInterface;
8+
9+
/**
10+
* Test error logging.
11+
*
12+
* @group graphql
13+
*/
14+
class LoggerTest extends GraphQLTestBase implements LoggerInterface {
15+
16+
use RfcLoggerTrait;
17+
18+
/**
19+
* Loggers calls.
20+
*
21+
* @var array
22+
*/
23+
protected $loggerCalls = [];
24+
25+
/**
26+
* {@inheritdoc}
27+
*/
28+
protected function setUp(): void {
29+
parent::setUp();
30+
31+
$schema = <<<GQL
32+
schema {
33+
query: Query
34+
}
35+
type Query {
36+
resolvesToNull: String!
37+
throwsException: String!
38+
takesIntArgument(id: Int!): String
39+
}
40+
GQL;
41+
42+
$this->setUpSchema($schema);
43+
44+
$this->mockResolver('Query', 'resolvesToNull', NULL);
45+
$this->mockResolver('Query', 'throwsException', function () {
46+
throw new \Exception('BOOM!');
47+
});
48+
$this->mockResolver('Query', 'takesIntArgument');
49+
50+
$this->container->get('logger.factory')->addLogger($this);
51+
}
52+
53+
/**
54+
* {@inheritdoc}
55+
*/
56+
public function log($level, $message, array $context = []) {
57+
$this->loggerCalls[] = [
58+
'level' => $level,
59+
'message' => $message,
60+
'context' => $context,
61+
];
62+
}
63+
64+
/**
65+
* Test if invariant violation errors are logged.
66+
*/
67+
public function testInvariantViolationError(): void {
68+
$result = $this->query('query { resolvesToNull }');
69+
$this->assertSame(200, $result->getStatusCode());
70+
// Client should not see the actual error.
71+
$this->assertSame([
72+
'errors' => [
73+
[
74+
'message' => 'Internal server error',
75+
'extensions' => [
76+
'category' => 'internal',
77+
],
78+
'locations' => [
79+
[
80+
'line' => 1,
81+
'column' => 9,
82+
],
83+
],
84+
'path' => [
85+
'resolvesToNull',
86+
],
87+
],
88+
],
89+
], json_decode($result->getContent(), TRUE));
90+
// The error should be logged.
91+
$this->assertCount(1, $this->loggerCalls);
92+
$loggerCall = reset($this->loggerCalls);
93+
$details = json_decode($loggerCall['context']['details'], TRUE);
94+
$this->assertSame($details['$operation']['query'], 'query { resolvesToNull }');
95+
$this->assertSame($details['$operation']['variables'], []);
96+
$this->assertCount(1, $details['$result->errors']);
97+
$this->assertSame(
98+
$details['$result->errors'][0]['message'],
99+
'Cannot return null for non-nullable field "Query.resolvesToNull".'
100+
);
101+
$this->assertStringContainsString(
102+
'For error #0: GraphQL\Error\InvariantViolation: Cannot return null for non-nullable field "Query.resolvesToNull".',
103+
$loggerCall['context']['previous']
104+
);
105+
}
106+
107+
/**
108+
* Test if exceptions thrown from resolvers are logged.
109+
*/
110+
public function testException(): void {
111+
$result = $this->query('query { throwsException }');
112+
$this->assertSame(200, $result->getStatusCode());
113+
// Client should not see the actual error.
114+
$this->assertSame([
115+
'errors' => [
116+
[
117+
'message' => 'Internal server error',
118+
'extensions' => [
119+
'category' => 'internal',
120+
],
121+
'locations' => [
122+
[
123+
'line' => 1,
124+
'column' => 9,
125+
],
126+
],
127+
'path' => [
128+
'throwsException',
129+
],
130+
],
131+
],
132+
], json_decode($result->getContent(), TRUE));
133+
// The error should be logged.
134+
$this->assertCount(1, $this->loggerCalls);
135+
$loggerCall = reset($this->loggerCalls);
136+
$details = json_decode($loggerCall['context']['details'], TRUE);
137+
$this->assertSame($details['$operation']['query'], 'query { throwsException }');
138+
$this->assertSame($details['$operation']['variables'], []);
139+
$this->assertCount(1, $details['$result->errors']);
140+
$this->assertSame($details['$result->errors'][0]['message'], 'BOOM!');
141+
$this->assertStringContainsString(
142+
'For error #0: Exception: BOOM!',
143+
$loggerCall['context']['previous']
144+
);
145+
}
146+
147+
/**
148+
* Test if client error are not logged.
149+
*/
150+
public function testClientError(): void {
151+
$result = $this->query('query { takesIntArgument(id: "boom") }');
152+
$this->assertSame(200, $result->getStatusCode());
153+
// The error should be reported back to client.
154+
$this->assertSame([
155+
'errors' => [
156+
0 => [
157+
'message' => 'Field "takesIntArgument" argument "id" requires type Int!, found "boom".',
158+
'extensions' => [
159+
'category' => 'graphql',
160+
],
161+
'locations' => [
162+
0 => [
163+
'line' => 1,
164+
'column' => 30,
165+
],
166+
],
167+
],
168+
],
169+
], json_decode($result->getContent(), TRUE));
170+
// The error should not be logged.
171+
$this->assertCount(0, $this->loggerCalls);
172+
}
173+
174+
}

‎tests/src/Kernel/GraphQLTestBase.php‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -70,6 +70,7 @@ protected function setUp(): void {
7070
$this->installEntitySchema('graphql_server');
7171
$this->installEntitySchema('configurable_language');
7272
$this->installConfig(['language']);
73+
$this->installEntitySchema('menu_link_content');
7374

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

0 commit comments

Comments
 (0)