Dblog module uses LEFT JOIN on the users table to select log entries on the overview display, but INNER JOIN to select on the detail display.
This results in log entries visible on the overview page that result in a blank display when viewing the entry detail for a user that has been deleted.

Usually, this would be a very minor issue, but on one of our sites, users are ephemeral for legal reasons - ie users are created on-the-fly from
the response of a secure webservice, and deleted on logout/timeout from the database. Of course this makes viewing log messages awkward after the user has logged out. LEFT JOIN returns a NULL uid from the users table and allows viewing log messages for deleted users as coming from anonymous.

Trivial patch follows to use LEFT JOIN on the dblog detail view.

Beta phase evaluation

Reference: https://www.drupal.org/core/beta-changes
Issue category Bug because dblog detail pages are broken if a deleted user triggered the error
Issue priority Not critical
Prioritized changes The main goal of this issue is usability since the dblog doesn't properly display log messages if the user that triggered the message has been deleted.
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

deadbeef’s picture

Status: Active » Needs review
FileSize
774 bytes

Patch to use LEFT JOIN in dblog detail view.

Status: Needs review » Needs work

The last submitted patch, 1: 1942682-dblog-detail-1.patch, failed testing.

zaporylie’s picture

Issue summary: View changes
Issue tags: +Needs reroll
zaporylie’s picture

Priority: Minor » Normal
Status: Needs work » Needs review
FileSize
969 bytes

After over a year this is still a problem. I've attached patch to see if changing INNER to LEFT will pass tests.

zaporylie’s picture

Assigned: Unassigned » zaporylie
Status: Needs review » Needs work
Issue tags: -Needs reroll

Tests passed by still doesn't work :) I will handle it.

zaporylie’s picture

Ok, this patch should be more than enough. Removed user join completely - user_load or User::load() (when #2322195: Replace all instances of user_load(), user_load_multiple(), entity_load('user') and entity_load_multiple('user') with static method calls will be fixed) will handle username instead.

jhedstrom’s picture

Issue tags: +Needs tests

This should have a test.

dawehner’s picture

Status: Needs review » Needs work

I think this can't work ... we still access

        '#account' => user_load($dblog->uid),

so I guess the proper fix is simply a LEFT JOIN ?

zaporylie’s picture

@dawehner But still, user_load will give us Anonymous user for non-existing uid, right? And uid is a part of $dblog object.
Not sure if join is needed here, correct me if I'm wrong.

zaporylie’s picture

Status: Needs work » Needs review
FileSize
2.56 KB
1.7 KB

This patch contains test coverage for deleted user issue. Nothing more since #7.

jhedstrom’s picture

user_load will give us Anonymous user for non-existing uid, right?

user_load() returns NULL for non-existing uid, not the anonymous user object.

zaporylie’s picture

That's right, but template_preprocess_username() doesn't really care if that's NULL or Anonymous user object, right?
Although, for performance reason, probably would be better to replace user_load($dblog->uid) with user_load($dblog->uid ? $dblog->uid : 0).
What do you think @jhedstrom?

zaporylie’s picture

ok, that's obviously not enough. We need also LEFT JOIN since uid in watchdog record keeps non-existing, non-zero value. I've added LEFT JOIN as well. I guess now it's ready for final review.

jhedstrom’s picture

@zaporylie could you upload a patch that just contains the new test to illustrate the current bug?

zaporylie’s picture

Sure I can. Here is a patch.

Status: Needs review » Needs work

The last submitted patch, 16: only-test-1942682-16.patch, failed testing.

zaporylie’s picture

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

Current codebase fails test - as expected - so I'm hiding file and bumping it back to Needs review.

jhedstrom’s picture

Issue summary: View changes
Status: Needs review » Reviewed & tested by the community
Issue tags: -Needs tests

Thanks @zaporylie!

#14 is good to go I think.

I added a beta phase evaluation to the issue summary.

xjm’s picture

Status: Reviewed & tested by the community » Needs work

Nice find. Thanks for the test-only patch and the beta evaluation.

I agree that this is a pretty clear bug, and non-disruptive, so it is allowed during the Drupal 8 beta. (Though the beta evaluation is slightly incomplete at the moment.)

  1. +++ b/core/modules/dblog/src/Controller/DbLogController.php
    @@ -234,12 +234,12 @@ public function overview() {
    -    if ($dblog = $this->database->query('SELECT w.*, u.name, u.uid FROM {watchdog} w INNER JOIN {users_field_data} u ON w.uid = u.uid WHERE w.wid = :id AND u.default_langcode = 1', array(':id' => $event_id))->fetchObject()) {
    +    if ($dblog = $this->database->query('SELECT w.*, u.uid FROM {watchdog} w LEFT JOIN {users} u ON u.uid = w.uid WHERE w.wid = :id', array(':id' => $event_id))->fetchObject()) {
    

    Can we get EXPLAINs for the old and new queries?

  2. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
    @@ -698,4 +698,37 @@ protected function assertLogMessage($log_message, $message) {
    +   * Tests if report detail view for non-existing user.
    +   *
    +   * Logs in the admin user, creates a database log event as ephemeral user
    +   * and tests the if detail page is not blank if this user does not exists
    +   * anymore.
    ...
    +    // Login as a user with access right to dblog.
    ...
    +    // Check if dblog event detail view contain correct message.
    ...
    +    // Check if dblog event detail view contain correct message.
    

    The docs could use a little fixing (maybe from a native English speaker) since these aren't complete sentences. There are a few missing articles (e.g. it should be "the correct message" rather than "correct message") and incorrect verb forms (e.g. it should be "contains" rather than "contain"). And so forth.

  3. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
    @@ -698,4 +698,37 @@ protected function assertLogMessage($log_message, $message) {
    +  public function testEphemeralUser() {
    +    // Create ephemeral user.
    

    The word "ephemeral" might not be familiar to everyone, so let's change this to something else throughout. Maybe "a temporary user"?

  4. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
    @@ -698,4 +698,37 @@ protected function assertLogMessage($log_message, $message) {
    +    $this->assertText('Dblog test log message', 'DBLog event node was displayed');
    ...
    +    $this->assertText('Dblog test log message', 'DBLog event node was displayed');
    

    We can remove the second parameter from these assertions; assertText() already provides a detailed message text.

jhedstrom’s picture

While running explains, I realized that the query in the patch in #16 switched back to using users instead of users_field_data.

Here's the explains of the queries as they should be, I think they are identical:

Old:

MariaDB [d8]> explain SELECT w.*, u.name, u.uid FROM watchdog w INNER JOIN users_field_data u ON w.uid = u.uid WHERE w.wid = 1 AND u.default_langcode = 1;
+------+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
| id   | select_type | table | type  | possible_keys | key     | key_len | ref   | rows | Extra       |
+------+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
|    1 | SIMPLE      | w     | const | PRIMARY,uid   | PRIMARY | 4       | const |    1 |             |
|    1 | SIMPLE      | u     | ref   | PRIMARY       | PRIMARY | 4       | const |    1 | Using where |
+------+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+

New:

MariaDB [d8]> explain SELECT w.*, u.name, u.uid FROM watchdog w LEFT JOIN users_field_data u ON w.uid = u.uid WHERE w.wid = 1 AND u.default_langcode = 1;
+------+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
| id   | select_type | table | type  | possible_keys | key     | key_len | ref   | rows | Extra       |
+------+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
|    1 | SIMPLE      | w     | const | PRIMARY,uid   | PRIMARY | 4       | const |    1 |             |
|    1 | SIMPLE      | u     | ref   | PRIMARY       | PRIMARY | 4       | const |    1 | Using where |
+------+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
zaporylie’s picture

I would be happy to provide another patch, but I have two doubts:

  1. Why we should use `users_field_data` instead of `users` even if all we want to do is validate if user exists or not?
  2. Why you've added `user_field_data`.`name` back to the query even if we are not using it anywhere?
jhedstrom’s picture

Adding the u.name back was a mistake in the above example as I was just copying the current existing query.

The change to users_field_data was from #1498664: Refactor user entity properties to multilingual, but I don't know that it is necessary here, since the langcode is hard-coded. Switching back to users should be fine.

zaporylie’s picture

Status: Needs work » Needs review
FileSize
2.04 KB
1.46 KB
2.58 KB

Before:

mysql> explain SELECT w.*, u.name, u.uid FROM watchdog w INNER JOIN users_field_data u ON w.uid = u.uid WHERE w.wid = 1 AND u.default_langcode = 1;
+----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
| id | select_type | table | type  | possible_keys | key     | key_len | ref   | rows | Extra       |
+----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
|  1 | SIMPLE      | w     | const | PRIMARY,uid   | PRIMARY | 4       | const |    1 |             |
|  1 | SIMPLE      | u     | ref   | PRIMARY       | PRIMARY | 4       | const |    1 | Using where |
+----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
2 rows in set (0.00 sec)

After:

mysql> explain SELECT w.*, u.uid FROM watchdog w LEFT JOIN users u ON w.uid = u.uid WHERE w.wid = 1
    -> ;
+----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
| id | select_type | table | type  | possible_keys | key     | key_len | ref   | rows | Extra       |
+----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
|  1 | SIMPLE      | w     | const | PRIMARY       | PRIMARY | 4       | const |    1 |             |
|  1 | SIMPLE      | u     | const | PRIMARY       | PRIMARY | 4       | const |    1 | Using index |
+----+-------------+-------+-------+---------------+---------+---------+-------+------+-------------+
2 rows in set (0.00 sec)

I had to re-roll patch (ref. #2322195: Replace all instances of user_load(), user_load_multiple(), entity_load('user') and entity_load_multiple('user') with static method calls) to fix 3. and 4.
I did my best to fix all grammar issues as well, but I am not a native English speaker so it should probably be reviewed and fixed by someone else.

The last submitted patch, 24: test-only-blank_detail_view_in-1942682-24.patch, failed testing.

jhedstrom’s picture

Issue summary: View changes
Status: Needs review » Reviewed & tested by the community

Great! Thanks zaporyli!

I think the latest patch addresses the feedback from above. Using the users table here instead is actually more performant since it is able to properly use an index.

xjm’s picture

Status: Reviewed & tested by the community » Fixed

Thanks @jhedstrom and @zaporylie -- glad to see we are using the index now!

The comment improvements look good as well. I made a couple very small fixes on commit:

diff --git a/core/modules/dblog/src/Tests/DbLogTest.php b/core/modules/dblog/src/Tests/DbLogTest.php
index 231607e..122fa8a 100644
--- a/core/modules/dblog/src/Tests/DbLogTest.php
+++ b/core/modules/dblog/src/Tests/DbLogTest.php
@@ -700,15 +700,14 @@ protected function assertLogMessage($log_message, $message) {
   }
 
   /**
-   * Confirms that the full message displays on the details page for a temporary
-   * user.
+   * Tests that the details page displays correctly for a temporary user.
    */
   public function testTemporaryUser() {
     // Create a temporary user.
     $tempuser = $this->drupalCreateUser();
     $tempuser_uid = $tempuser->id();
 
-    // Login the admin user.
+    // Log in as the admin user.
     $this->drupalLogin($this->adminUser);
 
     // Generate a single watchdog entry.
@@ -719,7 +718,7 @@ public function testTemporaryUser() {
     $this->drupalGet('admin/reports/dblog/event/' . $wid);
     $this->assertText('Dblog test log message');
 
-    // Delete user.
+    // Delete the user.
     user_delete($tempuser->id());
     $this->drupalGet('user/' . $tempuser_uid);
     $this->assertResponse(404);

The first one is just to get the one-line summary to one line under 80 chars (reference: https://www.drupal.org/node/1354#drupal); the others are just trivial fixes.

This issue is a normal bug fix, and doesn't include any disruptive changes, so it is allowed per https://www.drupal.org/core/beta-changes. Committed and pushed to 8.0.x (with credit for reviewers).

  • xjm committed 8b569be on 8.0.x
    Issue #1942682 by zaporylie, deadbeef, jhedstrom, dawehner: Blank detail...
xjm’s picture

Issue tags: +Needs followup
+++ b/core/modules/dblog/src/Controller/DbLogController.php
@@ -242,12 +242,12 @@ public function overview() {
-        '#account' => $this->userStorage->load($dblog->uid),
+        '#account' => $this->userStorage->load($dblog->uid ? $dblog->uid : 0),

Oops, I should have noticed this before, but we should be using a constant for the account here rather than 0. Can someone file a followup issue to clean that up? Thanks!

jhedstrom’s picture

jhedstrom’s picture

Status: Fixed » Reviewed & tested by the community

I don't actually see this commit.

jhedstrom’s picture

Status: Reviewed & tested by the community » Fixed

Nevermind, phpstorm was caching files.

Status: Fixed » Closed (fixed)

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