watchdog() passes the global $user object in the log record. dblog.module assumes $user is defined when watchdog is called:

<?php
function dblog_watchdog(array $log_entry) {
 
Database::getConnection('default', 'default')->insert('watchdog')
    ->
fields(array(
     
'uid' => $log_entry['user']->uid,
?>

The problem is that watchdog() can be called after global objects like $user is destructed, for example when a global output buffer handler is invoked (boost.module does this). The result is a PHP Warning because $user->uid is undefined.

If watchdog() may not be called under these conditions, it should be documented as such. Otherwise, it should have a fallback for when $user is not defined.

Files: 
CommentFileSizeAuthor
#31 drupal-598586-31.patch1.08 KBtim.plunkett
PASSED: [[SimpleTest]]: [MySQL] 39,116 pass(es).
[ View ]
#28 drupal-598586-28.patch1.1 KBtim.plunkett
PASSED: [[SimpleTest]]: [MySQL] 36,564 pass(es).
[ View ]
#21 598586-watchdog-21.patch3.99 KBZgear
PASSED: [[SimpleTest]]: [MySQL] 38,642 pass(es).
[ View ]
#16 598586-watchdog-16.patch4.09 KBdawehner
PASSED: [[SimpleTest]]: [MySQL] 35,722 pass(es).
[ View ]
#14 598586-watchdog-13.patch1.21 KBmatglas86
FAILED: [[SimpleTest]]: [MySQL] 38,553 pass(es), 0 fail(s), and 64 exception(s).
[ View ]
#14 598586-watchdog-13-2.patch2.44 KBmatglas86
FAILED: [[SimpleTest]]: [MySQL] 38,149 pass(es), 1 fail(s), and 8 exception(s).
[ View ]
#5 598586.patch827 bytesgrendzy
PASSED: [[SimpleTest]]: [MySQL] 31,558 pass(es).
[ View ]
#3 598586.patch823 bytesgrendzy
PASSED: [[SimpleTest]]: [MySQL] 31,579 pass(es).
[ View ]
#1 598586_add_isset.patch900 bytesdeekayen
PASSED: [[SimpleTest]]: [MySQL] 24,764 pass(es).
[ View ]

Comments

Status:Active» Needs review
StatusFileSize
new900 bytes
PASSED: [[SimpleTest]]: [MySQL] 24,764 pass(es).
[ View ]

This adds an isset check to the uid. If not set, it assigns uid 0.

Status:Needs review» Needs work

The code makes sense to me. It would probably benefit from a comment explaining that $user might not be there. Also it could be condensed as a ternary conditional.

Status:Needs work» Needs review
StatusFileSize
new823 bytes
PASSED: [[SimpleTest]]: [MySQL] 31,579 pass(es).
[ View ]

Status:Needs review» Needs work

+ // The user object may exist in all conditions, so 0 is substituted if needed.

You're missing "NOT".

Status:Needs work» Needs review
StatusFileSize
new827 bytes
PASSED: [[SimpleTest]]: [MySQL] 31,558 pass(es).
[ View ]

good catch! thanks.

Hrm. Will this cause a NOTICE when we check for isset() on a non-existent object? If $user is being destroyed before watchdog gets to it, then $log_entry['user'] won't exist at all (right?). In which case, we might get a NOTICE for checking on ->uid when $log_entry['user'] isn't there either? (I don't have a reliable way to test/create the fail case this is fixing…)

isset seems to tolerate a non-existant $log_entry['user']. I also have no idea how to reproduce the actual issue though.

@morbus since isset is a language construct, not a function and is designed to check for the the possible destruction caused by unset(), it and empty() I think are the only ways to safely check a non-existent variable without a notice.

In other words, it shouldn't cause a NOTICE if the variable isn't there.

Status:Needs review» Reviewed & tested by the community

Version:7.x-dev» 8.x-dev
Issue tags:+needs backport to D7

Status:Reviewed & tested by the community» Fixed

Committed to 8.x and 7.x. Thanks.

Issue tags:-needs backport to D7

Untagging since it's been committed to 7.x

Status:Fixed» Needs work

This fixes the problem for dblog_watchdog(), but not syslog_watchdog(). In any case, is fixing the problem this way in hook_watchdog() the best fix for this? There seems not much point in including $user in $log_entry if $user might sometimes be empty, requiring workarounds. Also there is a difference between user anonymous and $user undefined, but maybe that's a nicety that's not worth capturing.

Version:8.x-dev» 7.x-dev
Status:Needs work» Needs review
StatusFileSize
new2.44 KB
FAILED: [[SimpleTest]]: [MySQL] 38,149 pass(es), 1 fail(s), and 8 exception(s).
[ View ]
new1.21 KB
FAILED: [[SimpleTest]]: [MySQL] 38,553 pass(es), 0 fail(s), and 64 exception(s).
[ View ]

I fixed it the same way as the previous patch does but now for syslog_watchdog.

I looked at hook_watchdog. The only way I can think of doing this is adding a extra element uid to the array and use that in other methods and have user as a seperate object there.

There is a example of that in the second patch.

Status:Needs review» Needs work

The last submitted patch, 598586-watchdog-13-2.patch, failed testing.

Version:7.x-dev» 8.x-dev
Status:Needs work» Needs review
StatusFileSize
new4.09 KB
PASSED: [[SimpleTest]]: [MySQL] 35,722 pass(es).
[ View ]

Things should first be fixed in drupal8 and then be backported to 7.x

Here is a patch which fixes the tests in the second patch, as i think fixing this in watchdog() is the right place to do it.

Though there were some problems with the test, as they uses raw db_watchdog which changes.
In general i think db_watchdog doesn't have to check that, because people should just use watchdog() though i'm not sure about that.

Status:Needs review» Needs work

The last submitted patch, 598586-watchdog-16.patch, failed testing.

Status:Needs work» Needs review

#16: 598586-watchdog-16.patch queued for re-testing.

Status:Needs review» Reviewed & tested by the community

The last patch is for 8.x. I looked at it and to me it looks ready for commit.

Version:8.x-dev» 7.x-dev
Status:Reviewed & tested by the community» Patch (to be ported)
Issue tags:+needs backport to D7

Looks good. Committed/pushed to 8.x, moving to 7.x for backport.

StatusFileSize
new3.99 KB
PASSED: [[SimpleTest]]: [MySQL] 38,642 pass(es).
[ View ]

I applied the patch in 7.x then did a git diff, it worked without a hitch so here is your backport ^^

Status:Patch (to be ported)» Needs review

Status:Needs review» Reviewed & tested by the community

It has the correct number of fingers and toes, and no D8-specific anythings => RTBC. Thanks @Zgear!

Status:Reviewed & tested by the community» Fixed

Committed and pushed to 7.x. Thanks!

Version:7.x-dev» 8.x-dev
Status:Fixed» Needs work
Issue tags:+Needs Documentation

I'm a bit out of the loop these days but would I be right in thinking that the new key 'uid' in $log_entry needs some documentation? No mention of it in http://api.drupal.org/api/drupal/core!modules!system!system.api.php/function/hook_watchdog/8

Shouldn't we just create a follow up issue for that?

Regarding #26, @gpk is correct. Proper documentation is one of the core gates:
http://drupal.org/core-gates

Status:Needs work» Needs review
StatusFileSize
new1.1 KB
PASSED: [[SimpleTest]]: [MySQL] 36,564 pass(es).
[ View ]

Here's a first attempt.

Status:Needs review» Reviewed & tested by the community
Issue tags:-Needs Documentation

This looks correct to me.

Version:8.x-dev» 7.x-dev

Committed to 8.x. Thanks. Moving to 7.x.

StatusFileSize
new1.08 KB
PASSED: [[SimpleTest]]: [MySQL] 39,116 pass(es).
[ View ]

Rerolled to fix offset just in case.

Status:Reviewed & tested by the community» Fixed

Status:Fixed» Closed (fixed)
Issue tags:-needs backport to D7

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