Problem/Motivation

When an access denied error is logged to watchdog then all context why the error happened is lost. Example: a client requests /graphql and gets an access denied. The site admin cannot check why the access denied was triggered and what the cause is.

Proposed resolution

Add more 403 exception context to the log message in ExceptionLoggingSubscriber. That way an admin quickly sees why a request was access denied.

Remaining tasks

  1. Review patch and get consensus that we want this, then write tests.
  2. Wait for #3113876: The "Symfony\Component\HttpKernel\Event\GetResponseForExceptionEvent::getException()" method is deprecated since Symfony 4.4, use "getThrowable()" instead to land in 9.0.x.
  3. Final reviews + RTBC.
  4. Commit.

User interface changes

The log message at /admin/reports/dblog will have a better message.

Before

/admin/reports

After

Path: /admin/reports. Drupal\Core\Http\Exception\CacheableAccessDeniedHttpException: The 'access site reports' permission is required. in Drupal\Core\Routing\AccessAwareRouter->checkAccess() (line 117 of /var/www/html/core/lib/Drupal/Core/Routing/AccessAwareRouter.php).

API changes

None.

Data model changes

None.

Release notes snippet

TBD

CommentFileSizeAuthor
#47 3114122-9.1.x-47.patch3.31 KBjungle
#47 3114122-8.9.x-47.patch3.32 KBjungle
#47 3114122-8.8.x-47.patch3.35 KBjungle
#44 3114122-9.0.x-44-test-only.patch40.99 KBjungle
#43 interdiff-32-43.txt2.13 KBjungle
#43 3114122-43.patch3.32 KBjungle
#36 3114122-36-8.8.x.patch3.68 KBjungle
#34 interdiff-32-34.txt808 bytesjungle
#34 3114122-34.patch3.65 KBjungle
#32 interdiff-30-32.txt1.07 KBjungle
#32 3114122-32.patch3.7 KBjungle
#30 interdiff-27-30.txt3.27 KBjungle
#30 3114122-30.patch3.88 KBjungle
#27 interdiff-23-27.txt2.11 KBjungle
#27 3114122-27.patch2.74 KBjungle
#26 interdiff-23-26.txt1.81 KBjungle
#26 3114122-26.patch2.74 KBjungle
#23 interdiff-22-23.txt812 bytesjungle
#23 3114122-23.patch2.75 KBjungle
#22 interdiff-20-22.txt812 bytesjungle
#22 3114122-22.patch2.75 KBjungle
#20 interdiff-18-20.txt810 bytesjungle
#20 3114122-20.patch2.75 KBjungle
#18 interdiff-16-18.txt1.13 KBjungle
#18 3114122-18.patch2.75 KBjungle
#16 interdiff-12-16.txt1.94 KBjungle
#16 core-403-log-3114122-16.patch2.7 KBjungle
#2 core-403-log-3114122-2.patch1.04 KBklausi
#5 sort-direction-constants-3114088-6.patch784 bytesjungle
#9 core-403-log-3114122-9.patch2.94 KBjungle
#12 interdiff-3114122-9-12.txt1.62 KBjungle
#12 core-403-log-3114122-12.patch2.56 KBjungle
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

klausi created an issue. See original summary.

klausi’s picture

Status: Active » Needs review
FileSize
1.04 KB

Patch.

jungle’s picture

This is what I am looking for for a long time!!! Thanks, @klausi!

jungle’s picture

Assigned: Unassigned » jungle
jungle’s picture

Issue tags: -Needs tests
FileSize
784 bytes

A test added only, ignore interdiff as it’s unnecessary.

jungle’s picture

Version: 8.8.x-dev » 8.9.x-dev
jungle’s picture

Assigned: jungle » Unassigned
klausi’s picture

Status: Needs review » Needs work

Looks like you uploaded the wrong patch file, can you check?

jungle’s picture

Yes, a wrong patch uploaded, sorry!

jungle’s picture

Status: Needs work » Needs review

Status: Needs review » Needs work

The last submitted patch, 9: core-403-log-3114122-9.patch, failed testing. View results

jungle’s picture

ravi.shankar’s picture

Status: Needs work » Needs review

The last submitted patch, 12: core-403-log-3114122-12.patch, failed testing. View results
- codesniffer_fixes.patch Interdiff of automated coding standards fixes only.

klausi’s picture

Status: Needs review » Needs work
  1. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,41 @@ public function testLogEventPage() {
    +    $this->assertText('access denied');
    

    assertText() is deprecated and should not be used anymore.

  2. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,41 @@ public function testLogEventPage() {
    +    $this->assertRaw("Path: $uri");
    

    same for assertRaw()

  3. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,41 @@ public function testLogEventPage() {
    +    $this->assertRaw('117');
    

    we should not assert line numbers, then this test will easily break when the file is changed.

    Can we use $this->assertSession()->pageTextMatches() with a regular expression? That way we can leave out some details like the line number and just make sure that the permission name is on the page for example.

  4. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,41 @@ public function testLogEventPage() {
    +    $this->assertRaw( DRUPAL_ROOT . '/core/lib/Drupal/Core/Routing/AccessAwareRouter.php');
    

    there should be no space after "("

jungle’s picture

Status: Needs work » Needs review
FileSize
2.7 KB
1.94 KB

Thanks, @klausi for reviewing!

Patch adjusted according to #15

klausi’s picture

Status: Needs review » Needs work

Thanks, looks good to me! Some super minor small things we should fix and then this can be RTBC.

  1. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,37 @@ public function testLogEventPage() {
    +   * Test 403 log event page.
    

    Should be "Tests that a 403 event is logged with the exception triggering it."

  2. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,37 @@ public function testLogEventPage() {
    +
    

    Empty line that can be removed.

  3. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,37 @@ public function testLogEventPage() {
    +    $regex = '/Path.*CacheableAccessDeniedHttpException.*access site reports.* in.*checkAccess\(\).*line \d+ of.*AccessAwareRouter\.php/';
    

    We should check that the path /admin/reports" is in there.

  4. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,37 @@ public function testLogEventPage() {
    +
    

    Empty line that can be removed.

jungle’s picture

Status: Needs work » Needs review
FileSize
2.75 KB
1.13 KB

Thanks! Addressed #17 1, 2, 3, 4.

Status: Needs review » Needs work

The last submitted patch, 18: 3114122-18.patch, failed testing. View results

jungle’s picture

Status: Needs work » Needs review
FileSize
2.75 KB
810 bytes

The regex should escape '/' in the path

Status: Needs review » Needs work

The last submitted patch, 20: 3114122-20.patch, failed testing. View results

jungle’s picture

jungle’s picture

FileSize
2.75 KB
812 bytes
jungle’s picture

Status: Needs work » Needs review

Should pass this time. An extra markup surrounds the path, probably. But #18, 20 and 22 passed on my local. strange.

dww’s picture

Mostly looks great, thanks everyone!

A few nits/concerns. I won't set to NW, but I'm not RTBC'ing, either...

  1. +++ b/core/lib/Drupal/Core/EventSubscriber/ExceptionLoggingSubscriber.php
    @@ -38,8 +38,12 @@ public function __construct(LoggerChannelFactoryInterface $logger) {
    +    $this->logger->get('access denied')->warning('Path: @uri. %type: @message in %function (line %line of %file).', $error);
    

    I'm not sure about the legibility of how this is formatted, especially the @uri. part (with the dot after the path). But I don't have a better suggestion, so I guess this is fine as-is.

  2. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,35 @@ public function testLogEventPage() {
    +    $uri = '/admin/reports';
    

    We don't re-use this, so we could have it as a literal argument to drupalGet() a few lines down.

  3. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,35 @@ public function testLogEventPage() {
    +    // This is a 403 request.
    +    $this->drupalGet($uri);
    

    Shall we assert that we actually got a 403 response to this?

  4. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,35 @@ public function testLogEventPage() {
    +    // Login the admin user.
    +    $this->drupalLogin($this->adminUser);
    

    This comment is unneeded, the code documents itself.

  5. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,35 @@ public function testLogEventPage() {
    +    // Verify type.
    +    $assert_session->pageTextContains('access denied');
    

    Can we target this assertion more specifically so that we know we're hitting the type, not just seeing 'access denied' anywhere on the page?

  6. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,35 @@ public function testLogEventPage() {
    +    // Verify severity.
    +    $assert_session->pageTextContains('Warning');
    

    Also here -- let's make this a more specific assertion, if possible.

  7. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -225,7 +254,7 @@ protected function clearLogsEntries() {
    -  */
    +   */
    

    Someone will probably complain that this change is out of scope, so we might as well remove it before they get a chance. ;)

jungle’s picture

FileSize
2.74 KB
1.81 KB

Thanks, @dww for your detailed reviewing.

#25.1 skipped, 2 - 7 addressed.

jungle’s picture

#26 wrong interdiff, missed #25.7

contains(text(), '***')

And space after , to xpath queries.

dww’s picture

@jungle: #27 looks great, thanks!

Sadly, dreditor ate one of my comments that was supposed to be in #25. :( Don't know how that happened. Re-writing it here:

+++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
@@ -135,6 +135,32 @@ public function testLogEventPage() {
+    $regex = "/Path.*\/admin\/reports.*CacheableAccessDeniedHttpException.*access site reports.* in.*checkAccess\(\).*line \d+ of.*AccessAwareRouter\.php/";

I don't love this regexp. Too much use of .*, which should be used sparingly, if at all. If there's only whitespace differences between what's expected and what's appearing, we should use \s* to only match whitespace.

Bigger picture, I'd rather understand why this isn't matching up and solve it with a simpler / cleaner solution than a regexp peppered with .*.

Looking at the source for pageTextMatches(), it relies on getText(), which ultimately looks like this:

    /**
     * {@inheritdoc}
     */
    public function getText($xpath)
    {
        $text = $this->getFilteredCrawler($xpath)->text();
        $text = str_replace("\n", ' ', $text);
        $text = preg_replace('/ {2,}/', ' ', $text);

        return trim($text);
    }

Knowing that's what's happening to the page for the purposes of this assertion, I wonder if we can write the regexp more specifically...

Thanks!
-Derek

jungle’s picture

Assigned: Unassigned » jungle
Status: Needs review » Needs work

Thank you @dww! Good point. A new patch is coming soon.

jungle’s picture

jungle’s picture

Assigned: jungle » Unassigned
Status: Needs work » Needs review
jungle’s picture

Remove unnecessary assertions.

Status: Needs review » Needs work

The last submitted patch, 32: 3114122-32.patch, failed testing. View results

jungle’s picture

jungle’s picture

Status: Needs work » Needs review
jungle’s picture

A new patch for branch 8.8.x

9.0.x branch tests failed in #34, because of deprecation notices. should it be fixed in a separate issue?

jungle’s picture

dww’s picture

Title: ExceptionLoggingSubscriber should log 403 access denied reason » [PP-2] ExceptionLoggingSubscriber should log 403 access denied reason
Issue summary: View changes
Status: Needs review » Postponed

Thanks for sorting that out! Seems like this should wait until the dust settles on those two issues, since we can't safely commit this to 9.0.x until those are complete.

dww’s picture

Meanwhile, looking more closely at the latest patches...

  1. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,53 @@ public function testLogEventPage() {
    +    $base_path = base_path();
    ...
    +    $this->assertEquals($this->baseUrl . '/' . $uri, $href);
    ...
    +    $message_first_part = "Path: ${base_path}${uri}. ";
    

    We've got $this->baseUrl. Why do we also need $base_path? Why aren't we always using the same base URL for this test?

  2. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,53 @@ public function testLogEventPage() {
    +    $message_first_part = "Path: ${base_path}${uri}. ";
    +    $message_first_part .= 'Drupal\Core\Http\Exception\CacheableAccessDeniedHttpException: ';
    +    $message_first_part .= "The 'access site reports' permission is required. ";
    +    $message_first_part .= 'in Drupal\Core\Routing\AccessAwareRouter->checkAccess() ';
    +    $this->assertContains($message_first_part, $message_text);
    +    $message_last_part = DRUPAL_ROOT . '/core/lib/Drupal/Core/Routing/AccessAwareRouter.php';
    +    $this->assertContains($message_last_part, $message_text);
    

    Hrm, this is still a bit clumsy. This wasn't what I had in mind with my previous suggestion...

  3. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
    @@ -135,6 +135,53 @@ public function testLogEventPage() {
    +    $regex = "/.*line \d+ of.*/";
    +    $this->assertRegExp($regex, $message_text);
    

    That's still a very permissive regexp to be asserting. It works, but it's not great.

    I still believe it'd be possible to write a single regexp that cleanly matches the entire expected thing, without resorting to all this.

Thanks,
-Derek

jungle’s picture

@dww, thank you again for reviewing!

Re #39.1

$this->assertEquals($this->baseUrl . '/' . $uri, $href);

Here $href is a full URL, for example, http://example.com/admin/reports or http://example.com/subdir/admin/reports

$message_first_part = "Path: ${base_path}${uri}. ";

here, the path is a relative path. for example /admin/reports or /subdir/admin/reports

So baseUrl is not applicable here.

Re #39.2 and 3.

#15.3 we should not assert line numbers, then this test will easily break when the file is changed.

Writing one regex, it's good, but I don't think it's necessary, special chars in the message, make writing regex hard and less readable.

My approach is to break the message into 3 parts. the first part and last part, and the number part. the number part uses regexp only to address #15.3. If the message contains the first part and last part and matches the regex of number part, assuming it's the expected message. Maybe I should add a comment.

If you still prefer one-line regex, I will do.

dww’s picture

Re: #40 re #39.1:

Thanks for the explanation. Makes sense, but then maybe we need a better variable name for $base_path. B/c as it is, it's not at all clear from looking at the test what's going on here. E.g. $relative_base_path or something.

Re: #40 re: #39.2 and 3:

It's not really up to me. Personally, I think 1 well-crafted regexp would:
a) Cover everything.
b) Be easy enough to read.
c) Take a lot fewer lines of test code.
d) Be faster to test.

To help this particular regexp be more legible, you don't have to use '/' as the pattern boundary character. You could use something like '@' which wouldn't appear in the rest of the regexp, then you don't need to escape all the '/' chars we're expecting...

Completely untested, but something like:

$regex = "@Path /admin/reports\. Drupal\\Core\\Http\\Exception\\CacheableAccessDeniedHttpException: The 'access site reports' permission is required\. in Drupal\\Core\\Routing\\AccessAwareRouter->checkAccess\(\) \(line \d+ of .+/core/lib/Drupal/Core/Routing/AccessAwareRouter\.php)\.@";

Agreed we can't know (and don't want to assert) the root of the filesystem path where we find AccessAwareRouter.php. Maybe what you had is Good Enough(tm). But we could make sure the relative path within core itself is there, which shouldn't change. Note that I'm proposing .+ here, not .* since we expect there will be at least 1 character matched (.* can match 0 things, which wouldn't be valid here).

jungle’s picture

Thank you! Will submit a new patch today or tomorrow according to your feedback, have to admit that I am not good at regexp :p

jungle’s picture

Re #41: $base_path vs $relative_base_path

$base_path isn't used in the patch anymore. But, personally, I prefer $base_path, as it's being used in the core a lot.

  • /**
     * Returns the base URL path (i.e., directory) of the Drupal installation.
     *
     * Function base_path() adds a "/" to the beginning and end of the returned path
     * if the path is not empty. At the very least, this will return "/".
     *
     * Examples:
     * - http://example.com returns "/" because the path is empty.
     * - http://example.com/drupal/folder returns "/drupal/folder/".
     */
    function base_path() {
      return $GLOBALS['base_path'];
    }
  • /**
     * Process callback for local image filter.
     */
    function _filter_html_image_secure_process($text) {
      // Find the path (e.g. '/') to Drupal root.
      $base_path = base_path();
    

Re #41, regex

Thanks, learnt that / is not the only delimiter available. Your $regex is almost right. 3 tiny changes made.

  1. \\ --> \\\\ have to use 4 backslashes to escape \, see a blog post for more, https://www.developwebsites.net/match-backslash-preg_match-php
  2. @Path /admin/reports --> @Path: .+admin/reports. Missing :,and as the base path matters. The path could be like /admin/reports or /sub.directory/admin/reports, and the base path may contains meta chars like . as you can see, so use .+ is applicable, or have to consider escaping meta chars.
  3. .+/core/lib/Drupal, agree with you on using .+ , one more reason is that the path may contain meta chars too.
  4. .php)\.@ --> .php\)\.@
jungle’s picture

Combined with the patch from #3113876 to make sure that #3113876 is the only one blocker.

jungle’s picture

Title: [PP-2] ExceptionLoggingSubscriber should log 403 access denied reason » [PP-1] ExceptionLoggingSubscriber should log 403 access denied reason
1) Drupal\Tests\quickedit\FunctionalJavascript\QuickEditIntegrationTest::testArticleNode
Field node/1/body/en/full did not match its expectation selector (.cke_editable_inline), actual HTML: Hello world!I do not know what to say…I wish I were eloquent.
Failed asserting that 'Hello world!I do not know what to say…I wish I were eloquent.' is identical to true.

The one failed test is irrelevant I think. And yes, 3113876 is the only one blocker. and it's RTBC'd.

jungle’s picture

jungle’s picture

Title: [PP-1] ExceptionLoggingSubscriber should log 403 access denied reason » ExceptionLoggingSubscriber should log 403 access denied reason
Status: Postponed » Needs review
FileSize
3.35 KB
3.32 KB
3.31 KB

3113876 landed

dww’s picture

Status: Needs review » Reviewed & tested by the community

Sweet, thanks!

Re: #43:
1: Oh right. Silly PHP. :/
2: Yeah, good point. .+ is fine here.
3: 👍
4: 👍

Test now looks great. I intentionally broke this feature in various ways, and the test is failing as expected in each one.

Re: #47:

At this point, as a new feature with a string change, I'd be shocked if the core committers will accept this in the 8.8.x branch. I guess it's nice to provide the 8.8.x patch, just in case, but don't get your hopes up. ;)

Although 8.9.0-beta1 is out, I do think this is viable for the 8.9.x branch, since it's not very disruptive (I don't think we consider the formatting of watchdog messages "API" in any way) and this definitely improves debugging access and 403s significantly. Helping site builders and developers get access control right is an extremely important thing, and anything we can do to help them make sure they're getting it right is worth doing. It is a string change, but it's almost entirely placeholders, and it's only visible to site admins reading the logs (not in the main UI anywhere), so if it's not translated, it's no big deal.

I'm still a bit concerned about #25.1. The message has periods in it in multiple places, although there aren't full sentences. The message also continues after the period inside the exception message with "in ..." as if it's all 1 thing. Reading the code, it looks plausible it could be a real sentence, but the @message itself can be multiple sentences. My sense is we could improve this before commit, but I still don't have a solid suggestion, so I'm not going to NW for this.

In fact, I'll RTBC (since I don't see anything else to improve) and let the core committer(s) decide. ;)

Thanks again!
-Derek

jungle’s picture

Thank you again for reviewing @dww! Do not you sleep? :p

so if it's not translated, it's no big deal.

Yes, and it is encouraged that do not translate exception messages right now. #2055851: Remove translation of exception messages is the issue to remove translations from exception messages and Needs Review :)

I had one real experience troubleshooting 403 with this patch in my work, it's useful to me. I am fine with #25.1, as long as those key info are there. But yes, would be great always if we could make it better.

The patch for 9.1.x is applicable to 9.0.x as well.

(Updated Remaining tasks in IS)

dww’s picture

@jungle re: #49

Do not you sleep? :p

Not enough. :p A question that also applies to you, it seems! ;)

Yes, and it is encouraged that do not translate exception messages right now.

I'm not talking about the exception text. I'm talking about this:

'Path: @uri. %type: @message in %function (line %line of %file).'

The words: "Path", "in", "line" and "of". ;) Again, it's only visible to admins, and those 4 words are probably understandable to anyone. As you say, the @message part will be expanded with something even more complicated that will be in English. So yeah, I don't think this is a legitimate reason not to get this into 8.9.x, even though beta1 is out. That's what I was trying to preemptively address.

Cheers,
-Derek

Version: 8.9.x-dev » 9.1.x-dev

Drupal 8.9.0-beta1 was released on March 20, 2020. 8.9.x is the final, long-term support (LTS) minor release of Drupal 8, which means new developments and disruptive changes should now be targeted against the 9.1.x-dev branch. For more information see the Drupal 8 and 9 minor version schedule and the Allowed changes during the Drupal 8 and 9 release cycles.

  • catch committed 5fbd9c7 on 9.1.x
    Issue #3114122 by jungle, klausi, dww: ExceptionLoggingSubscriber should...
catch’s picture

Status: Reviewed & tested by the community » Fixed

Committed 5fbd9c7 and pushed to 9.1.x. Thanks!

A bit close to RC for this one I think, so leaving it there.

jungle’s picture

@catch, thanks for committing! Is it possible backporting to 8.9.x? This is useful for troubleshooting 403 errors. It's a small change but makes a difference. Hoping that this could be backported to 8.9.x or at least 9.0.x.

dww’s picture

@jungle re: #54: @catch already answered exactly that question at the end of #53:

A bit close to RC for this one I think, so leaving it there.

I don't personally agree with that assessment. It's a change to a watchdog message. I don't know why we'd consider this risky or potentially disruptive. If I were a release manager (and we can all be thankful I'm not), I'd be happy to call this a 'task' and get it into 9.0.x and 8.9.x. ;) /shrug

Cheers,
-Derek

jungle’s picture

Re #55, yes, I saw that and I knew that means no chance to be backported. Just wondering is there a 2nd chance. Anyway, it's still possible to use this patch in other branches, just another patch to manage :)

catch’s picture

Version: 9.1.x-dev » 8.9.x-dev
Category: Feature request » Task

OK took another look I think it's fine, but better error messages are tasks rather than features ;)

  • catch committed 5a9823d on 9.0.x
    Issue #3114122 by jungle, klausi, dww: ExceptionLoggingSubscriber should...

  • catch committed da574bf on 8.9.x
    Issue #3114122 by jungle, klausi, dww: ExceptionLoggingSubscriber should...
dww’s picture

Whoot! 🎉😉 Thanks for the 2nd look, @catch. Maybe I'm qualified to be a release manager, after all. 😜

jungle’s picture

Thanks, @catch for giving it a 2nd chance! Thanks to @dww again for your tireless and patiently reviews. And thanks @klausi for your initial works. 🍻

klausi’s picture

Great work jungle! I see you contributing everywhere, big thanks from me ❤️

Thanks also dww for convincing catch :)

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.

mbovan’s picture

I have created a related issue to remove unnecessary backtrace string #3167390: ExceptionLoggingSubscriber should not log backtrace string on access denied exceptions.