ExceptionLoggingSubscriber should not log HTTP 4XX errors using PHP logger channel

Good catch, 4XX errors are client side errors!

@Chi
Do you mind explaining why its not enough to just change the logger channel on the on404 and on403 pages and be done with it? It is not entirely obvious, at least for me, why some of the code needs to be rewritten. I guess there are totally good reasons for that.

+++ b/core/modules/dblog/dblog.routing.yml
@@ -27,7 +27,7 @@ dblog.page_not_found:
-    type: 'page not found'
+    type: 'not found'
   requirements:

@@ -36,7 +36,7 @@ dblog.access_denied:
-    type: 'access denied'
+    type: 'forbidden'

I think changing these logger channels is a problem. I could imagine existing tools filter messages by these strings.

Thank you @Chi, I hope this makes sense for you as well.

Do you think we could get some test coverage to prove that we now log more than just the 403/404 errors?

is it possible to get last logged entries in a Kernel test? I've tried to fetch them from watchdog table but failed.

The problem is you are not using {watchdog} and therefore you are querying the watchdog table from your current site and not the created by phpunit.

This came up as a daily bugsmash target.

Rerolled #21 but changing the todo for Drupal 10.2.0

@smustgrave changing the logger channel seems like a breaking change that should be delayed to 11.0.0

Changed to 11.0.0 and fixed the failing db log test.

Updated test case.

+        $channel = strtolower($status_texts[$status_code]);

This can trigger a warning if the $status_code is not in the list of status_texts. We don't know if some client/server/app can use a custom error code that we are not aware of... Not sure if we should log this at all, or just ignore it...

+        $status_texts = Response::$statusTexts;
+
+        // BC layer to preserve existing logger channels.
+        // @TODO Remove this in Drupal 11.0.0.
+        $status_texts[403] = 'access denied';
+        $status_texts[404] = 'page not found';
+
+        $channel = strtolower($status_texts[$status_code]);

Maybe we can avoid copying the statusText into a new array. What about checking $status_text = Response::$statusTexts[$status_code] ?? NULL;

And then use 2 ifs to override 'access denied' and 'page not' found texts.

+        // @TODO Remove this in Drupal 11.0.0.
+        $status_texts[403] = 'access denied';
+        $status_texts[404] = 'page not found';

I think it should be

 // @todo Remove the BC layer in Drupal 11.
 // @see https://www.drupal.org/project/drupal/issues/2828706

+        $uri = $event->getRequest()->getRequestUri();
+        $this->logger->get($channel)->warning('@uri', ['@uri' => $uri]);

No need to create a temp variable:

$this->logger->get($channel)->warning('@uri', ['@uri' => $event->getRequest()->getRequestUri()]);

Something like that?

Do we really need separate logger channels, or should we just have a shared "http" logger channel for the 4xx errors that aren't 403/404? They don't seem common enough to warrant their own.

That I don't know I can answer. But I do like the idea of 403s not logging as a php exception but that's may just be me.

Adding a generic "http client error" logger channel seems sufficient to me, and the specific status code could be added to the context array.

Fixed the test case. Not sure best practice for dealing with subdirectory running on d.o but add a string replace for now.

Fix Unit Fail

Thank you Anchal_gupta for the patch but please include an interdiff so we can see what has changed.

From what I can tell patch #43 is the same as #41 so remove credit for that.

Updated the tests to remove the status codes that weren't being checked by the code change.

I think we want to go with the approach provided in #37 and #39. Something like this perhaps? (Beware untested code, just sharing the approach mentioned in #37 and #39 so others can continue this as part of the Bug Smash Initiative.

Added what was provided in #45 lets see what happens.

Also added IS update just to make sure we have an agreed upon approach.

What about this?

Not sure about the error in testUncaughtFatalError will have to investigate later.

This is looking good to me. The one thing I might suggest (as I mentioned in #39) would be to add status_code to the context array. My philosophy is the more context/metadata/etc. provided to loggers, the better. But in general drupal core doesn't go out of its way to add helpful context (aside from log message placeholders) so that's just my humble opinion.

Not sure I follow?

@smustgrave I think what @mfb is trying to say is, send the 4xx code as part of the $context array. Because it is hidden behind the generic client error.

Like this?

Yes I think that's the jist of the suggestion.

i closed #3039266: Generic logging for 4xx errors as a duplicate, moving credit.

1. 
   +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
   +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
   @@ -183,6 +183,41 @@ public function test403LogEventPage() {
   
   @@ -183,6 +183,41 @@ public function test403LogEventPage() {
        $this->assertMatchesRegularExpression($regex, $message[0]->getText());
      }
    
   +  /**
   +   * Tests that 4xx errors, outside 403 and 404, are logged with the exception.
   +   */
   +  public function testClientErrors() {
   +    // Trigger BadRequestException.
   

   I'm not sure we need this if we have the Kernel test - depending on the answer to the question about the kernel test.

2. +++ b/core/tests/Drupal/KernelTests/Core/EventSubscriber/ExceptionLoggingSubscriberTest.php
   @@ -0,0 +1,57 @@
   +
   +    $channel_map = [
   +      403 => 'access denied',
   +      404 => 'page not found',
   +      // Do not check the 500 status code here because it would be caught by
   +      // Drupal\Core\EventSubscriberExceptionTestSiteSubscriber which has lower
   +      // priority.
   +      501 => 'php',
   +      502 => 'php',
   +      503 => 'php',
   +    ];
   

   This isn't testing the non-403/404 4xx errors that this issue is about, should it be?

Removed functional test

#67 looks good.

1. +++ b/core/lib/Drupal/Core/EventSubscriber/ExceptionLoggingSubscriber.php
   @@ -88,10 +104,16 @@ public function onException(ExceptionEvent $event) {
   +      else {
   +        if ($status_code >= 400 && $status_code < 500) {
   +          $method = 'onClientError';
   +        }
   

   shouldn't this be elseif? as much as I hate elseif, its odd to see an if inside an else

2. +++ b/core/modules/system/tests/modules/error_test/error_test.routing.yml
   @@ -40,3 +40,10 @@ error_test.trigger_renderer_exception:
   +error_test.trigger_bad_request_exception:
   +  path: '/error-test/trigger-bad_request-exception'
   +  defaults:
   +    _controller: '\Drupal\error_test\Controller\ErrorTestController::triggerBadRequestException'
   +  requirements:
   +    _access: 'TRUE'
   
   +++ b/core/modules/system/tests/modules/error_test/src/Controller/ErrorTestController.php
   @@ -5,6 +5,7 @@
   +use Symfony\Component\HttpFoundation\Exception\BadRequestException;
   
   @@ -98,4 +99,12 @@ function () {
   +  /**
   +   * Trigger a bad request exception.
   +   */
   +  public function triggerBadRequestException() {
   +    define('SIMPLETEST_COLLECT_ERRORS', FALSE);
   +    throw new BadRequestException();
   +  }
   

   is this used? the test seems to be hitting an existing route

3. +++ b/core/tests/Drupal/KernelTests/Core/EventSubscriber/ExceptionLoggingSubscriberTest.php
   @@ -0,0 +1,61 @@
   +    // Make sure that HTTP exceptions are logged into correct channel.
   +    $this->installSchema('dblog', ['watchdog']);
   

   Let's not use the database to collect the log messages, we can just make the kernel test a logger 💪

   See https://www.previousnext.com.au/blog/making-your-drupal-8-kernel-tests-f... for an example

Or even simpler, use the test logger like in #3134349: \Drupal\language\LanguageNegotiator does not handle PluginNotFoundException and break the site completely - learnt something new 🔥

Let me work on #69

Resolved the 1st issue from #69 and created PR.

What about #2 and #3 @sourabhjain?

Going to cancel the test run, its a waste of DA resources without addressing the feedback.

Attempted to address all points.

This issue is being reviewed by the kind folks in Slack, #need-reveiw-queue. We are working to keep the size of Needs Review queue [2700+ issues] to around 400 (1 month or less), following Review a patch or merge request as a guide.

Thanks for working on this, found some more stuff to remove from the test ;).

1. diff --git a/core/modules/system/tests/modules/error_test/src/Controller/ErrorTestController.php b/core/modules/system/tests/modules/error_test/src/Controller/ErrorTestController.php
   index b15bb9b00c..b550b4fda4 100644
   --- a/core/modules/system/tests/modules/error_test/src/Controller/ErrorTestController.php
   +++ b/core/modules/system/tests/modules/error_test/src/Controller/ErrorTestController.php
   @@ -5,6 +5,7 @@
    use Drupal\Core\Controller\ControllerBase;
    use Drupal\Core\Database\Connection;
    use Symfony\Component\DependencyInjection\ContainerInterface;
   +use Symfony\Component\HttpFoundation\Exception\BadRequestException;
    
    /**
     * Controller routines for error_test routes.
   @@ -98,4 +99,12 @@ function () {
        ];
      }
    
   +  /**
   +   * Trigger a bad request exception.
   +   */
   +  public function triggerBadRequestException() {
   +    define('SIMPLETEST_COLLECT_ERRORS', FALSE);
   +    throw new BadRequestException();
   +  }
   +
    }
   

   To address #69.2 the latest patch removed the route that wasn't used, but I think this needs to be removed as well. Without the route this is now dead code.

2. diff --git a/core/tests/Drupal/FunctionalTests/Bootstrap/UncaughtExceptionTest.php b/core/tests/Drupal/FunctionalTests/Bootstrap/UncaughtExceptionTest.php
   index c85cc3c6e1..969c364890 100644
   --- a/core/tests/Drupal/FunctionalTests/Bootstrap/UncaughtExceptionTest.php
   +++ b/core/tests/Drupal/FunctionalTests/Bootstrap/UncaughtExceptionTest.php
   @@ -94,7 +94,7 @@ public function testUncaughtException() {
      public function testUncaughtFatalError() {
        $fatal_error = [
          '%type' => 'TypeError',
   -      '@message' => 'Drupal\error_test\Controller\ErrorTestController::Drupal\error_test\Controller\{closure}(): Argument #1 ($test) must be of type array, string given, called in ' . \Drupal::root() . '/core/modules/system/tests/modules/error_test/src/Controller/ErrorTestController.php on line 65',
   +      '@message' => 'Drupal\error_test\Controller\ErrorTestController::Drupal\error_test\Controller\{closure}(): Argument #1 ($test) must be of type array, string given, called in ' . \Drupal::root() . '/core/modules/system/tests/modules/error_test/src/Controller/ErrorTestController.php on line 66',
          '%function' => 'Drupal\error_test\Controller\ErrorTestController->Drupal\error_test\Controller\{closure}()',
        ];
        $this->drupalGet('error-test/generate-fatals');
   

   Since we don't use the error_test module in the test at all and we thus don't need to make any modifications to that module anymore, this can most likely also be reverted.

3. +  /**
   +   * {@inheritdoc}
   +   */
   +  protected function setUp(): void {
   +    parent::setUp();
   +    // Prepare the logger for collecting the expected critical error.
   +    $this->container->get($this->testLogServiceName)->cleanLogs();
   +  }
   

   Further down in the test method, we're already calling $this->assertEmpty($this->container->get($this->testLogServiceName)->cleanLogs()); before we start triggering errors. I don't think we need to call this twice. I think asserting that the logger is empty in the test is a good idea, so we should probably just remove the setup method.

4. +  protected static $modules = ['system', 'test_page_test', 'dblog'];
   

   and

   +    // Make sure that HTTP exceptions are logged into correct channel.
   +    $this->installSchema('dblog', ['watchdog']);
   

   Given that we now use a test logger, I don't think we need need dblog anymore, do we?

Tagging "Needs followup" for #76.

This came up again in #3377310: 400 exceptions result from requests for old asset paths which are missing the "theme" query string, possibly from cached pages.

Resolve remarks from #77

Opened #3392245: ExceptionLoggingSubscriber should not log HTTP 5XX errors using PHP logger channel

Points from #77 do appear to be resolved.

Committed/pushed to 11.x, cherry-picked to 10.2.x and 10.1.x, thanks!