User module's flood controls should do better logging [D7 backport]

Thanks Balazs!

I've updated the IS with log snippets from D7 (which are almost identical anyway).

I think we'll need to change the calls to form_set_error() to drupal_set_message() as when the access denied page is returned, there is no login form displayed - which is probably why tests will fail when they check for the error text. This was the same in the D8 version.

Found out together with #tatarbj that assertEqual is deprecated in D7. Therefore, the D8 function assertEquals is most likely the function that replaced D7's assertEqual.

Changed assertEquals to assertEqual and will add the patch to this issue to see if the test will succeed this time.

The changes in this patch should fix the unexpected error 200.

Also, according to my mentor, the text for line 38 should be different, so I adjusted that aswell.

My mentor suggested I'd make an interdiff.
I followed the tutorial "easy mode" on this page:
https://www.drupal.org/documentation/git/interdiff#comment-9688981

I don't know if I did it right. I don't think so, because it shows more then my last changes.

Added @count to t variables.

Tried to add interdiff again, but again, I don't think it worked correctly. I think it's because I apply the patch with phpStorm because git apply is being a b*tch.

Thank you so much for your help, @tatarbj! I appreciate it :)

Issue wasn't put on "Needs review" due to a Drupal ci error. The testserver was stuck, and even though the tests all succeeded, the build failed, and thus, the testserver put this issue on "Needs work".

Later, @mixologic reran the tests and this time it did succeed. But the issue was not put to "Needs review", so that's what I'm doing right now.

I think drupal_access_denied() was in slightly the wrong place so it was being called when an incorrect password was supplied.

Furthermore, I think we need to call drupal_exit() afterwards as otherwise, the form API carries on processing the form submission and we end up with Drupal effectively trying to emit two responses; as reflected by warnings like these in the log:

Oct  5 12:09:28 xp drupal: http://drupal7x.xp|1538741368|user|10.0.3.1|http://drupal7x.xp/user|http://drupal7x.xp/user|0||Flood control blocked login attempt for fred from 6-10.0.3.1.
Oct  5 12:09:28 xp drupal: http://drupal7x.xp|1538741368|access denied|10.0.3.1|http://drupal7x.xp/user|http://drupal7x.xp/user|0||user
Oct  5 12:09:28 xp drupal: http://drupal7x.xp|1538741368|php|10.0.3.1|http://drupal7x.xp/user|http://drupal7x.xp/user|0||Warning: Cannot modify header information - headers already sent by (output started at /data/drupal-7.x/includes/common.inc:2783) in drupal_send_headers() (line 1490 of /data/drupal-7.x/includes/bootstrap.inc).
Oct  5 12:09:28 xp drupal: http://drupal7x.xp|1538741368|php|10.0.3.1|http://drupal7x.xp/user|http://drupal7x.xp/user|0||Warning: Cannot modify header information - headers already sent by (output started at /data/drupal-7.x/includes/common.inc:2783) in drupal_send_headers() (line 1490 of /data/drupal-7.x/includes/bootstrap.inc).
Oct  5 12:09:28 xp drupal: http://drupal7x.xp|1538741368|php|10.0.3.1|http://drupal7x.xp/user|http://drupal7x.xp/user|0||Warning: session_start(): Cannot start session when headers already sent in drupal_session_start() (line 287 of /data/drupal-7.x/includes/session.inc).

There are other examples of calling drupal_exit() after drupal_access_denied() in core, e.g. elsewhere in the user module:

https://api.drupal.org/api/drupal/modules%21user%21user.pages.inc/functi... / https://cgit.drupalcode.org/drupal/tree/modules/user/user.pages.inc?h=7....

...and these in the contact module (quite a similar case in that they're both straight after flood control has blocked a submission):

https://api.drupal.org/api/drupal/modules%21contact%21contact.pages.inc/... / https://cgit.drupalcode.org/drupal/tree/modules/contact/contact.pages.in...

https://api.drupal.org/api/drupal/modules%21contact%21contact.pages.inc/... / https://cgit.drupalcode.org/drupal/tree/modules/contact/contact.pages.in...

With this updated patch in place, we get the 403 in the logs as intended but without the "headers already sent" warnings:

==> syslog <==
Oct  5 12:20:13 xp drupal: http://drupal7x.xp|1538742013|user|10.0.3.1|http://drupal7x.xp/user|http://drupal7x.xp/user|0||Flood control blocked login attempt for fred from 6-10.0.3.1.
Oct  5 12:20:13 xp drupal: http://drupal7x.xp|1538742013|access denied|10.0.3.1|http://drupal7x.xp/user|http://drupal7x.xp/user|0||user

==> access.log <==
drupal7x.xp 10.0.3.1 - - [05/Oct/2018:12:20:13 +0000] "POST /user HTTP/1.1" 403 6529

Testing it out in the browser by repeatedly giving the wrong password in the /user form, the 403 page displays the flood control message correctly.

However, triggering flood control via the login block on another page seems to result in an infinite loop (AFAICS the form validation happens again when Drupal tries to render the login block on the access denied page)... so we'll need to fix that.

Also looking more closely at the flood control log entry:

Flood control blocked login attempt for fred from 6-10.0.3.1.

...which comes from:

watchdog('user', 'Flood control blocked login attempt from %ip.', array('%ip' =>isset($form_state['flood_control_user_identifier']) ? $form_state['flood_control_user_identifier'] : ip_address()));

We may be better just using ip_address() rather than $form_state['flood_control_user_identifier'] if the IP is all that we want to log.

I think the test failures were a result of moving drupal_access_denied().

I don't think the tests should actually be checking for a 403 when flood control has not been triggered.

This new patch should resolve that.

However, I think even if tests pass, there's still a big problem in that if Drupal tries to render a login form (e.g. the login block) on the access denied page, we never get as far as the drupal_exit() and we have an infinite loop.

What's happening is drupal_deliver_html_page(MENU_ACCESS_DENIED) is called and that renders a 403 page:

          // Standard 403 handler.
          drupal_set_title(t('Access denied'));
          $return = t('You are not authorized to access this page.');
        }
        print drupal_render_page($return); 

...and if the login block is included on that page, validation happens again and we end up back at user_login_final_validate() again.

So we need to rethink this...

Perhaps it's as simple as... instead of calling drupal_access_denied() and trying to exit, just set the 403 header and let the form processing finish. The 403 response is really what we're trying to achieve.

One problem with that approach is that a site with a custom 403 page set up will not have that invoked in this case...

Submitting a patch which should just fix the previous test failures, then I'll work on making the outlined change (i.e. emit a 403 but don't call drupal_access_denied()).

Not sure what happened there; I've tried to queue a retest.

In the meantime, here's a patch which doesn't call drupal_access_denied() in order to avoid the infinite loop. Instead it adds the 403 header.

This seems to work AFAICS.

We could also add another call to watchdog for consistency i.e. reproduce this:

      case MENU_ACCESS_DENIED:

        // Print a 403 page.
        drupal_add_http_header('Status', '403 Forbidden');
        watchdog('access denied', check_plain($_GET['q']), NULL, WATCHDOG_WARNING);

...from drupal_deliver_html_page().

That would ensure that anyone monitoring for those "access denied" watchdog messages would pick these up. Otherwise, there may only be the 403s in the access log. On the other hand, perhaps that's sufficient, and we're already calling watchdog to record the flood control blocking the login attempt.

This patch also tweaks those calls to watchdog to remove $form_state['flood_control_user_identifier'] and simply use ip_address().

I've updated this backport to add a new hook to emulate the events we're adding in the D8/9 version.

This also adds tests for the new hook.

We'd want a Change Record for this new hook along similar lines to https://www.drupal.org/node/3067148

Modules could use the new hook to do things like send a notification when a user account is blocked because of excessive failed login attempts, or add an IP to firewall rule, for example.

I'll provide a change record for it

Just created the change record.
Please review it.

Great, thanks @paulocs - I've made a couple of small tweaks to the CR but I think it's pretty much ready.

One more thing we need to do is add an entry to modules/user/user.api.php for the new hook_user_flood_control().

Setting to NW for that.

I've added hook_user_flood_control() to modules/user/user.api.php as mentioned.

In doing so, I also realised that the user module could use this hook itself to do the logging - which is pretty much how this works in D9:

https://git.drupalcode.org/project/drupal/-/blob/9.1.x/core/modules/user...

So you could argue that there's now some duplication in the tests as we're specifically testing the hook and checking for the log entries which will have come from an implementation of the hook also. However, the implementation could change and it's seldom a bad thing to add more test coverage.

Note to self: trailing whitespace in the user.api.php entry, which could be fixed on commit.

+++ b/modules/user/user.api.php
@@ -472,6 +472,37 @@ function hook_user_role_delete($role) {
+    ¶

nit - wrong white space added

----

It should be possible to opt-out of the default logging behavior at run-time however else when someone is using DB logging they can use a DOS attempt via the flood logging mechanism.

Per mcdruid in D9 it's already possible to opt-out via settings, so let's port that here as well.

Good catch!

Added in an opt-out variable similar to the D9 implementation.

Fixed (with a couple of tweaks to comments that I'd added in the last few patches).

Thanks everyone that contributed; it's great to get this in - we started work on it in Drupal Dev Days Lisbon 2018!