feat(server): log unsafe errors #1258

Leksat · 2022-01-18T12:57:36Z

pmelab

Kingdutch · 2022-02-08T08:59:31Z

src/Entity/Server.php

+    if (empty($result->errors)) {
+      return;
+    }
+
+    $unsafeErrors = array_filter($result->errors, function ($e) {
+      return !($e instanceof ClientAware) || !$e->isClientSafe();
+    });
+    $isPreviousErrorLogged = FALSE;
+    foreach ($unsafeErrors as $error) {
+      if ($error->getPrevious() instanceof \Throwable) {
+        _drupal_log_error(ErrorUtil::decodeException($error->getPrevious()));
+        $isPreviousErrorLogged = TRUE;
+      }
+    }
+
+    if ($unsafeErrors) {


I'd like to move the filter into the foreach. This means we don't have an N + M (N being all, M being the server errors) but only an N loop. It can also slightly improve readability :)

The type of $result->errors is always an array. So if it's empty the foreach loop is just skipped, there's no need for an additional empty check.

Suggested change

if (empty($result->errors)) {

return;

}

$unsafeErrors = array_filter($result->errors, function ($e) {

return !($e instanceof ClientAware) || !$e->isClientSafe();

});

$isPreviousErrorLogged = FALSE;

foreach ($unsafeErrors as $error) {

if ($error->getPrevious() instanceof \Throwable) {

_drupal_log_error(ErrorUtil::decodeException($error->getPrevious()));

$isPreviousErrorLogged = TRUE;

}

}

if ($unsafeErrors) {

$hasServerErrors = FALSE;

$hasLoggedPrevious = FALSE;

foreach ($result->errors as $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 ($e instanceof ClientAware && $e->isClientSafe()) {

continue;

}

$hasServerErrors = 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) {

_drupal_log_error(ErrorUtil::decodeException($error->getPrevious()));

$hasLoggedPrevious = TRUE;

}

}

if ($hasServerErrors) {

We could even replace the if ($hasServerErrors) { with a guard clause, but I'm not sure that'd necessarily improve readability.

if (!$hasServerErrors) { return; } // \Drupal::logger here

I'm wondering if trying to json_encode $result->errors will cause us any grief in testing. See sebastianbergmann/phpunit#4371 (comment) for details, which previously led to f9c573a

Kingdutch · 2022-02-08T09:00:27Z

src/Entity/Server.php

+      \Drupal::logger('graphql')->error(
+        "There were errors during a GraphQL execution.\n{see_previous}\nDebug:\n<pre>\n{debug}\n</pre>",
+        [
+          'see_previous' => $isPreviousErrorLogged ? 'See the previous log messages for the error details.' : '',


I'm personally never a fan of the "see the previous log messages" because on busy sites they're hardly ever next to each other. Would there be a good way to get those errors all into a single error log message?

On systems that send alerts based on the amount of errors this can also easily trip monitoring for a single request, which may not be desirable (e.g. if a single request caused the same error to happen multple times).

klausi

Thanks, makes sense to me! @Kingdutch has some good points, please fix those.

klausi · 2022-02-08T15:16:36Z

src/Entity/Server.php

+    $isPreviousErrorLogged = FALSE;
+    foreach ($unsafeErrors as $error) {
+      if ($error->getPrevious() instanceof \Throwable) {
+        _drupal_log_error(ErrorUtil::decodeException($error->getPrevious()));


are we sure we want to use _drupal_log_error()? It also sets an HTML response, which does not make sense to me in a graphql API context (when displaying errors is enabled)? But then again it contains a lot of useful code for decoding the error, so this should be fine.

Leksat · 2022-02-09T07:05:45Z

@Kingdutch @klausi I did the changes.

@Kingdutch

I'm wondering if trying to json_encode $result->errors will cause us any grief in testing

I don't know what to use as a replacement. I chose json_encode because it was producing the most pretty output with the lowest effort.

@klausi

Line   src/Entity/Server.php                                  
581    Unreachable statement - code above always terminates.

This error makes no sense to me. Also it appears only with PHP 7. Could it be that it is caused by the recent PHPStan update?

klausi · 2022-02-09T14:18:26Z

Looks like a phpstan bug, I will try to resolve that!

klausi · 2022-02-09T14:28:11Z

PHPStan fixed in #1261 , merged & running the tests again.

klausi · 2022-02-09T16:08:24Z

Tested this with our project setup and it works for me!

It would be cool to have a test case for this, it should be viable since we are also testing full query requests in ResultTest for example. Not sure how easy it is to check the logs in a test or set a mock log service for the assertion.

Now thinking about it I'm not sure that the Server entity is the correct place to do this logging. The executor seems more like the best fitting place? I see doExecuteUncached() there that is probably the right place. What do you think?

Leksat · 2022-02-10T10:32:16Z

@klausi thanks! I implemented both suggestions.

@Kingdutch for some reason I cannot re-request a review from you.

klausi

Wow, outstanding work @Leksat !!! Something like this is exactly what I was thinking of, great job.

Will merge this now.

klausi · 2022-02-10T16:29:04Z

tests/src/Kernel/GraphQLTestBase.php

    $this->installEntitySchema('graphql_server');
    $this->installEntitySchema('configurable_language');
    $this->installConfig(['language']);
+    $this->installEntitySchema('menu_link_content');


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

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.

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).

It was happening in the new test I created.

klausi · 2022-02-10T16:33:08Z

src/GraphQL/Execution/Executor.php

+    }
+
+    if ($hasUnsafeErrors) {
+      \Drupal::logger('graphql')->error(


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

klausi · 2022-02-10T16:33:59Z

tests/src/Kernel/Framework/LoggerTest.php

+    });
+    $this->mockResolver('Query', 'takesIntArgument');
+
+    $this->container->get('logger.factory')->addLogger($this);


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

Kingdutch · 2022-02-11T10:59:28Z

for some reason I cannot re-request a review from you.

Yeah I'm not officially a maintainer, just someone who uses GraphQL and has opinions :D

* 8.x-4.x: test(dataprovider): Rename dataprovider functions to not be accidentally tested (drupal-graphql#1266) fix(EntityLoad): Return NULL on NULL entity IDs when composing entity load (drupal-graphql#1174) fix(entity_reference): Return emtpy arrays instead of NULL (drupal-graphql#1265) chore(voyager): JS dependency updates with yarn audit chore(explorer): JS dependency updates with yarn audit test(coder): Update Coder to 8.3.14 (drupal-graphql#1264) test(phpstan): Enable PHPStan on PHP 8 by disabling PHP opcache (drupal-graphql#1262) feat(server): Log unsafe server errors for better error tracing (drupal-graphql#1258) test(phpstan): Ignore PHPStan warning directly in code with a comment (drupal-graphql#1263) test(phpstan): Ignore a false unreachable statement error (drupal-graphql#1261) test(phpstan): Update PHPStan and dependencies (drupal-graphql#1257) test(php): Add PHP 8.1 for testing (drupal-graphql#1256) test(core): Update Drupal core to 9.3 for testing (drupal-graphql#1255)

…al-graphql#1258)

feat(server): log unsafe errors

cf5a7a1

Leksat mentioned this pull request Jan 18, 2022

Log errors with Drupal logger #1195

Closed

chore: fix phpstan/phpcs errors

0aed48b

Leksat force-pushed the log-unsafe-errors branch from 70f3040 to 0aed48b Compare January 18, 2022 13:26

pmelab approved these changes Feb 7, 2022

View reviewed changes

Kingdutch reviewed Feb 8, 2022

View reviewed changes

klausi requested changes Feb 8, 2022

View reviewed changes

Leksat added 4 commits February 9, 2022 09:14

chore: redo the logic as suggested by @Kingdutch

5139962

chore: rename the method

9ee8313

chore: log everything in one message

5508a41

chore: better variable name

063ba6a

Merge branch '8.x-4.x' into log-unsafe-errors

db10276

klausi added the 4.x label Feb 9, 2022

Leksat added 3 commits February 10, 2022 10:30

chore: move logging to Executor

bc583de

test: add logger tests

7f830b1

fix: fix phpcs error

93b7ec8

Leksat requested a review from klausi February 10, 2022 10:30

klausi approved these changes Feb 10, 2022

View reviewed changes

klausi merged commit e211199 into drupal-graphql:8.x-4.x Feb 10, 2022

Leksat deleted the log-unsafe-errors branch February 10, 2022 17:01

klausi pushed a commit to klausi/graphql that referenced this pull request Sep 21, 2023

feat(server): Log unsafe server errors for better error tracing (drup…

58e34ff

…al-graphql#1258)

-    if (empty($result->errors)) {
-      return;
-    }
-    $unsafeErrors = array_filter($result->errors, function ($e) {
-      return !($e instanceof ClientAware) || !$e->isClientSafe();
-    });
-    $isPreviousErrorLogged = FALSE;
-    foreach ($unsafeErrors as $error) {
-      if ($error->getPrevious() instanceof \Throwable) {
-        _drupal_log_error(ErrorUtil::decodeException($error->getPrevious()));
-        $isPreviousErrorLogged = TRUE;
-      }
-    }
-    if ($unsafeErrors) {
+    $hasServerErrors = FALSE;
+    $hasLoggedPrevious = FALSE;
+    foreach ($result->errors as $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 ($e instanceof ClientAware && $e->isClientSafe()) {
+        continue;
+      }
+      $hasServerErrors = 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) {
+        _drupal_log_error(ErrorUtil::decodeException($error->getPrevious()));
+        $hasLoggedPrevious = TRUE;
+      }
+    }
+     if ($hasServerErrors) {

feat(server): log unsafe errors #1258

feat(server): log unsafe errors #1258

Uh oh!

Conversation

Leksat commented Jan 18, 2022

Uh oh!

pmelab left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

klausi left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Leksat commented Feb 9, 2022

Uh oh!

klausi commented Feb 9, 2022

Uh oh!

klausi commented Feb 9, 2022

Uh oh!

klausi commented Feb 9, 2022

Uh oh!

Leksat commented Feb 10, 2022

Uh oh!

klausi left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Kingdutch Feb 11, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Kingdutch commented Feb 11, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Kingdutch Feb 11, 2022 •

edited

Loading