Demote user log entries from "notice" to "info".

There are two more cases which I think should also be changed to info.

In core/modules/user/src/Form/UserPasswordForm.php, submitForm()

    if ($account) {
      // Mail one time login URL and instructions using current language.
      $mail = _user_mail_notify('password_reset', $account);
      if (!empty($mail)) {
        $this->logger('user')
          ->notice('Password reset instructions mailed to %name at %email.', [
            '%name' => $account->getAccountName(),
            '%email' => $account->getEmail(),
          ]);
      }
    }
    else {
      $this->logger('user')
        ->notice('Password reset form was submitted with an unknown or inactive account: %name.', [
          '%name' => $form_state->getValue('name'),
        ]);
    }

Updated patch according to #5

I think most of the changes such as password resets, sessions and one time logins are OK, except for:

1. +++ b/core/modules/user/src/EventSubscriber/UserFloodSubscriber.php
   @@ -50,10 +50,10 @@ public function blockedUser(UserFloodEvent $floodEvent) {
   -        $this->logger->notice('Flood control blocked login attempt for uid %uid from %ip', ['%uid' => $uid, '%ip' => $ip]);
   ...
   -      $this->logger->notice('Flood control blocked login attempt for uid %uid', ['%uid' => $uid]);
   
   @@ -65,7 +65,7 @@ public function blockedUser(UserFloodEvent $floodEvent) {
   -      $this->logger->notice('Flood control blocked login attempt from %ip', ['%ip' => $floodEvent->getIp()]);
   

   I would suggest that flood controls are "normal but significant" and should remain as notices. These do not occur very often in normal operation.

2. +++ b/core/modules/user/src/Form/UserLoginForm.php
   @@ -249,12 +249,12 @@ public function validateFinal(array &$form, FormStateInterface $form_state) {
   -          $this->logger('user')->notice('Login attempt failed for %user.', ['%user' => $form_state->getValue('name')]);
   ...
   -          $this->logger('user')->notice('Login attempt failed from %ip.', ['%ip' => $this->getRequest()->getClientIp()]);
   

   Perhaps also login failures are "normal but significant"?

3. +++ b/core/modules/user/user.module
   @@ -673,7 +673,7 @@ function _user_cancel($edit, $account, $method) {
   -      $logger->notice('Blocked user: %name %email.', ['%name' => $account->getAccountName(), '%email' => '<' . $account->getEmail() . '>']);
   
   @@ -684,7 +684,7 @@ function _user_cancel($edit, $account, $method) {
   -      $logger->notice('Deleted user: %name %email.', ['%name' => $account->getAccountName(), '%email' => '<' . $account->getEmail() . '>']);
   

   Deleting a user is certainly a "significant" event. Should blocking be considered the same?

By this patch #6 we can Demote user log entries from "notice" to "info".

Rerolled for 9.3.x / 9.4.x. Resolved conflicts.

PSR-3 says notice is "Normal but significant events" and info is "Interesting events. Example: User logs in, SQL logs."

So it seems clear that user login should be logged as "info" :) Meanwhile the events that longwave flagged in #7 do seem more like "normal but significant".

The concept of "notice" is definitely tricky, partly because RFC 5424 and PHP errors use completely different sets of levels, and software has to figure out how to map between the two.. I think of PHP notices as being more error-like than RFC 5424 notices..

@mfb I guess the main reason for such clean up (at least in my case) is that code (php) issues are not equal to application logic issues, so maybe users should see code issues as separate dashboard? Or at least we should provide documentation for that. I.e., for external log systems, it should send only php issues. I think both types of issues are important, but for different roles. Application logic issues for creating content, blocked users, or possibly some failed orders are critical. For example, if order failed, it is a critical issue for business, but not the same as "undefined is not a function"-like one. Worst scenario if there is connection to external api, and if api respond with 500 issue, because of something failed, i.e. your transaction failed in a middle, or if it returns 5xx response but with validation error - user's credit card doesn't have enough funds. Main question for me – should we collect both errors together? If yes, then ->notice("flood: User blocked") and ->notice("php: Undefined index") are the same level. But in other case better to split them.

@zviryatko Yes it's a good idea to assign errors to the right team and alert them, whether through configuring Monolog or configuring an external log system.. Probably lots more community documentation on this is needed :)

This is a good reminder that a change record will be needed, as folks may already have setup custom logging logic, so adding a tag for that.

Created a draft change record: https://www.drupal.org/node/3259469

It's currently out of sync with the most recent patch on this issue. In light of @longwave's review at #7 I'd suggest rolling a new patch with slightly fewer changes, so that there can be consensus to get something committed :)

This needs another reroll and also needs some of the demotions removed as per #7

Rerolled patch for 10.1.x with #7 demotions.
Please check
thanks

Fixed CCF indentation.

#24 works for me, all the messages that have been demoted are informational only.

This seems sensible. The CR is succinct but sufficient as well. I made a small edit to the CR to make the before/after clearer.

I think we should consider this for the release notes also. My reasoning is that folks could have automated tooling that audits these logs, including security-incident-related stuff, and such tooling might just silently stop reporting rather than triggering an error condition that a site owner would investigate and follow to the CR. So marking NW for the release note. Thanks!

Saving issue credits for the original issue report, necessary rerolls, and helpful reviews and discussions that make it clear this fix is the right choice.

Added release notes; fixed typo in change record

Thansk @mfb.

The patch no longer applies, so will need a reroll.

reroll for 10.1.x

@Nitin shrivastava Thank you for your attempts to reroll this patch.

Unfortunately, the reroll is incorrect. If you compare the diffstats using either Dreditor or git on the command line, you can see that the two patches have a different number of lines changed. The first has:
7 files changed, 10 insertions, 10 deletions.

The second has:
7 files changed, 9 insertions, 9 deletions.

If you look at RoleForm with your rerolled patch applied, you can see where there is still another instance that needs to be changed:

    if ($status == SAVED_UPDATED) {
      $this->messenger()->addStatus($this->t('Role %label has been updated.', ['%label' => $entity->label()]));
      $this->logger('user')->info('Role %label has been updated.', ['%label' => $entity->label(), 'link' => $edit_link]);
    }
    else {
      $this->messenger()->addStatus($this->t('Role %label has been added.', ['%label' => $entity->label()]));
      $this->logger('user')->notice('Role %label has been added.', ['%label' => $entity->label(), 'link' => $edit_link]);
    }

When you reroll patches, please ensure all of the changes from the previous patch are included. You can use the git diff --stat command for an overview of the changes, and you should read both the original patch and your reroll.

Review the instructions on rerolling patches for a full list of steps to take for the reroll and things to check. If you need assistance with a reroll, you can also get assistance in Drupal Slack.

Thanks!

Tagging for reroll again and hiding the incorrect patch.

Re Rolled for 10.1.x Based on patch from #24.

Re Rolled to patch as GITLAB is having hiccups with MR.

Tested #36 on Drupal 10.1.x

- The issue summary makes sense and provides the necessary details
- The patch applies cleanly
- The severity changes from notice to info
- Release notes have been provided
- Did a code review and there are no noticeable issues

Marking this issue as RTBC

Thanks @Bhanu951 for your reroll and @ameymudras for your review. I did not think to look at the change in markup as a result of the patch, so that's helpful. In the future, you can embed your screenshot images in the issue summary "User interface changes" section to make the issue easier to review. I've done that now.

I also edited the release note so that the link text will be unique and meaningful out of context. (This is an accessibility requirement.)

With the patch applied, I reviewed which User module events are still notices:

[ayrton:maintainer | Tue 09:23:58] $ grep -r "notice" core/modules/user/*
core/modules/user/src/Form/UserLoginForm.php:          $this->logger('user')->notice('Login attempt failed for %user.', ['%user' => $form_state->getValue('name')]);
core/modules/user/src/Form/UserLoginForm.php:          $this->logger('user')->notice('Login attempt failed from %ip.', ['%ip' => $this->getRequest()->getClientIp()]);
core/modules/user/src/Form/UserMultipleCancelConfirm.php:    // Output a notice that user 1 cannot be canceled.
core/modules/user/src/EventSubscriber/UserFloodSubscriber.php:        $this->logger->notice('Flood control blocked login attempt for uid %uid from %ip', ['%uid' => $uid, '%ip' => $ip]);
core/modules/user/src/EventSubscriber/UserFloodSubscriber.php:      $this->logger->notice('Flood control blocked login attempt for uid %uid', ['%uid' => $uid]);
core/modules/user/src/EventSubscriber/UserFloodSubscriber.php:      $this->logger->notice('Flood control blocked login attempt from %ip', ['%ip' => $floodEvent->getIp()]);
core/modules/user/user.install:      \Drupal::logger('update')->notice(
core/modules/user/user.module:      $logger->notice('Blocked user: %name %email.', ['%name' => $account->getAccountName(), '%email' => '<' . $account->getEmail() . '>']);
core/modules/user/user.module:      $logger->notice('Deleted user: %name %email.', ['%name' => $account->getAccountName(), '%email' => '<' . $account->getEmail() . '>']);

For these:

• First and second results, failed logins: Notice-worthy; useful fo to audit e.g. if someone is attempting to brute-force user accounts, or if there are site-wide authentication issues.
• Third result: Unrelated use of the word in a comment.
• Fourth through sixth results, users blocked for flooding: Notice-worthy, e.g. for auditing if the site is under attack, or if a user account has been compromised and is being used for spam.
• Seventh result: I checked in core/modules/user/user.install and the next line is:
  

          'The role %role has had the following non-existent permission(s) removed: %permissions.',
  

  That's important information, because it affects the user's access to the site and may indicate a data integrity issue.

• Eighth result, blocked user. Useful to log because it disrupts user access and could be indicative of a problem.
• Ninth result, deleted user. Ditto.

Finally, I reviewed the change with git diff --color-words and confirmed that the only changes are the method "notice" being changed to "info" in the 10 relevant places.

Committed to 10.1.x, and published the change record. Also tagging for the release notes in case we decide to include it there. Thanks everyone!

Looks like we've made a little rabbit hole of log level demotion issues; maybe we can look at #3255699: Demote routine content entity log entries from "notice" to "info" next.

This was already added to the 10.1.0 release notes draft. We should ensure that related issues update the same CR.