Problem/Motivation

There is a line of code $context['user'] = $this->currentUser; inside of LoggerChannel::log() that was introduced as part of #1289536: Switch Watchdog to a PSR-3 logging framework.

When the log message includes some type of wildcard referencing {user*}, then \Drupal\Core\Logger\LogMessageParser::parseMessagePlaceholders() converts {users*} to @users* and then, because we have a context key 'user', it tries to put the AccountProxy object in there, which gives you this recoverable fatal error like: AccountProxy could not be converted to string

I tracked the code of the dblog and syslog and there is no use of the user object from the context array, just the uid. This makes sense since the username of a user can change, the only thing that does not vary is the user id.

Proposed resolution

  • Remove the non used line.
  • Create a change record that explicit indicates this lines was removed in case a contrib module was depending on this.

Please also credit to @penyaskito and @berdir in this issue.

Comments

dagmar created an issue. See original summary.

dagmar’s picture

Issue summary: View changes
dagmar’s picture

Change record added.

zuhair_ak’s picture

Status: Active » Needs review
StatusFileSize
new550 bytes

Added the patch removing the line

dagmar’s picture

StatusFileSize
new1.13 KB
new1.67 KB

Thanks @zuhair_ak.

Here is a test only version that exposes the problem.

Please add @berdir and @penyaskito to issue credits since they reported the problem before in #2980802 and #2703877.

dagmar’s picture

StatusFileSize
new656 bytes
new1.17 KB

That didn't work as expected.

The last submitted patch, 6: 2986294-6-test-only.patch, failed testing. View results

dagmar’s picture

Issue summary: View changes
msankhala’s picture

Status: Needs review » Needs work
+++ b/core/modules/dblog/tests/src/Kernel/DbLogControllerTest.php
@@ -76,4 +76,30 @@ public function testDbLogCorrupted() {
+   * Test that 'user' variable is no longer available by default in context array.

I have two small observations. One line function summary is exceeding 80 characters. Changing the variable => key will reduce the length.

+++ b/core/modules/syslog/tests/src/Kernel/SyslogTest.php
@@ -75,4 +75,12 @@ public function testSyslogSeverity() {
+   * Test that 'user' variable is no longer available by default in context array.

Same as above.

pritishkumar’s picture

StatusFileSize
new1.18 KB
new540 bytes

"Test that 'user' variable is no longer available by default in context array."

I could see this comment summary only in core/modules/syslog/tests/src/Kernel/SyslogTest.php file.

Changed accordingly.

zuhair_ak’s picture

Status: Needs work » Needs review

Changing the status to 'Needs Review'

dagmar’s picture

Issue summary: View changes
dagmar’s picture

Status: Needs review » Reviewed & tested by the community

The change record is done. The patch looks good, and I checked a few logging modules (mongodb, monolog, redis_watchdog, simple_access_log) and it seems they are not using $context['user'] as part of the logger.

catch’s picture

Status: Reviewed & tested by the community » Needs work
+++ b/core/modules/syslog/tests/src/Kernel/SyslogTest.php
@@ -75,4 +75,12 @@ public function testSyslogSeverity() {
 
+  /**
+   * Test that 'user' key is no longer available by default in context array.
+   */
+  public function testUserInContextArray() {
+    \Drupal::logger('my_module')->warning('Hello {user}');
+    \Drupal::logger('my_module')->warning('Hello {users_field_data}');
+  }
+

I don't think we need to add a test here. It's useful to have the failing test in this issue to show the bug, but in terms of adding the code to core, it's adding a test for something that no-longer exists in the code base.

dagmar’s picture

Status: Needs work » Reviewed & tested by the community

Thanks @catch. In that case patch #4 is the one to go.

catch’s picture

Thanks. From #13 it looks like contrib loggers are using this? If they are then we might not be able to remove this.

dagmar’s picture

Sorry I meant to say they are not using this feature.

alexpott’s picture

Status: Reviewed & tested by the community » Needs review

In \Drupal\Core\Logger\LoggerChannel::log() we're still merging in a user default. Should we be doing that? In some ways it acts as a BC layer but, on the other hand, it is super confusing.

    // Merge in defaults.
    $context += [
      'channel' => $this->channel,
      'link' => '',
      'user' => NULL,
      'uid' => 0,
      'request_uri' => '',
      'referer' => '',
      'ip' => '',
      'timestamp' => time(),
    ];
alexpott’s picture

Also, whilst we are here can we create a follow up to discuss removing the try{ } catch {}

      try {
        if ($this->currentUser) {
          $context['uid'] = $this->currentUser->id();
        }
      }
      catch (\Exception $e) {
        // An exception might be thrown if the database connection is not
        // available or due to another unexpected reason. It is more important
        // to log the error that we already have so any additional exceptions
        // are ignored.
      }

As far as I can see there is never a situation anymore when getting the ID from the current_user service can throw an exception. This was resolved in #2753733: AccountProxy can do unnecessary user loads to get an ID

dagmar’s picture

StatusFileSize
new801 bytes

Let's see if the removal of 'user' from $context doesn't have side effects with the current tests.

msankhala’s picture

Status: Needs review » Reviewed & tested by the community

I can confirm that the patch #20 applies cleanly and remove the $context['user']. After applying the patch I was not able to find any reference to user in $context.

curl https://www.drupal.org/files/issues/2018-07-28/2986294-20.patch | git apply -v
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   801  100   801    0     0   1448      0 --:--:-- --:--:-- --:--:--  1451
Checking patch core/lib/Drupal/Core/Logger/LoggerChannel.php...
Applied patch core/lib/Drupal/Core/Logger/LoggerChannel.php cleanly.
grep -rn 'user' core/lib/Drupal/Core/Logger
core/lib/Drupal/Core/Logger/LoggerChannelInterface.php:21: * of log(): request_uri, referer, ip, user, uid.
core/lib/Drupal/Core/Logger/LoggerChannelInterface.php:46:   * Sets the current user.
core/lib/Drupal/Core/Logger/LoggerChannelInterface.php:48:   * @param \Drupal\Core\Session\AccountInterface|null $current_user
core/lib/Drupal/Core/Logger/LoggerChannelInterface.php:49:   *   The current user object.
core/lib/Drupal/Core/Logger/LoggerChannelInterface.php:51:  public function setCurrentUser(AccountInterface $current_user = NULL);
core/lib/Drupal/Core/Logger/LoggerChannelFactory.php:36:      // If we have a container set the request_stack and current_user services
core/lib/Drupal/Core/Logger/LoggerChannelFactory.php:41:        $instance->setCurrentUser($this->container->get('current_user'));
core/lib/Drupal/Core/Logger/LoggerChannel.php:75:   * The current user object.
core/lib/Drupal/Core/Logger/LoggerChannel.php:150:  public function setCurrentUser(AccountInterface $current_user = NULL) {
core/lib/Drupal/Core/Logger/LoggerChannel.php:151:    $this->currentUser = $current_user;
core/lib/Drupal/Core/Logger/LogMessageParser.php:26:        // If the message is "User {username} created" the variable key will be
core/lib/Drupal/Core/Logger/LogMessageParser.php:27:        // just "username".
catch’s picture

catch’s picture

Status: Reviewed & tested by the community » Fixed

Committed 3fa89d6 and pushed to 8.7.x. Thanks!

  • catch committed bc043fd on 8.7.x
    Issue #2986294 by dagmar, pritish.kumar, zuhair_ak, catch, alexpott:...
longwave’s picture

Also opened #2998731: Remove $context['user'] from DbLogTest and FakeLogEntries as a followup for some test classes that still include the 'user' parameter.

Status: Fixed » Closed (fixed)

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

quietone’s picture

publish the change record