Page MenuHomePhabricator

Exception "At least one of: RCID, revision ID, and log ID MUST be specified" from ManualLogEntry::publish
Closed, ResolvedPublicPRODUCTION ERROR

Description

Error

Request ID: XJPtAgpAAEsAABrnAzwAAADO
Request URL: POST /w/api.php

message
MWException: At least one of: RCID, revision ID, and log ID MUST be specified when adding or removing a tag from a change!
trace
#0 /srv/mediawiki/php-1.33.0-wmf.22/includes/changetags/ChangeTags.php(229): ChangeTags::updateTags(array, array, NULL, NULL, integer, NULL, NULL)
#1 /srv/mediawiki/php-1.33.0-wmf.22/includes/logging/LogEntry.php(811): ChangeTags::addTags(array, NULL, NULL, integer)
#2 /srv/mediawiki/php-1.33.0-wmf.22/includes/deferred/MWCallableUpdate.php(34): Closure$ManualLogEntry::publish()
#3 /srv/mediawiki/php-1.33.0-wmf.22/includes/deferred/DeferredUpdates.php(273): MWCallableUpdate->doUpdate()
#4 /srv/mediawiki/php-1.33.0-wmf.22/includes/deferred/DeferredUpdates.php(219): DeferredUpdates::runUpdate(MWCallableUpdate, Wikimedia\Rdbms\LBFactoryMulti, string, integer)
#5 /srv/mediawiki/php-1.33.0-wmf.22/includes/deferred/DeferredUpdates.php(143): DeferredUpdates::execute(array, string, integer)
#6 /srv/mediawiki/php-1.33.0-wmf.22/includes/MediaWiki.php(909): DeferredUpdates::doUpdates(string)
#7 /srv/mediawiki/php-1.33.0-wmf.22/includes/MediaWiki.php(733): MediaWiki->restInPeace(string, boolean)
#8 [internal function]: Closure$MediaWiki::doPostOutputShutdown()

Impact

I suspect change tags are meant to be programmatically associated with certain user actions, and are now no longer being associated. To a first approximation, this cannot be recovered in an easy way and is likely permanently damaged.

Notes

This is a generic error can can be triggered by multiple different features. There are a handful of log entries from before 1.33-wmf.22 from other features. However, it increased by 1000x, which makes it likely a regression.

capture.png (592×2 px, 45 KB)

Event Timeline

zeljkofilipin triaged this task as Unbreak Now! priority.Mar 21 2019, 11:30 PM
zeljkofilipin subscribed.

Train blockers are UBN!

Explanation what's going on here:

The current issue is a result of two actions, first, we found out that system does not store changes tags for logs published only to UDP, that was an unintentionally broken some time ago and fixed in rMW1da4a38757e2: LogEntry: Restore logic to add change tags on udp-only publish / T218110. This alone could cause some troubles, as from now MediaWiki core tries to save ChangeTags when those are present (not only when those are published to rc|rcandudp). Then in rMW384ab964cdde: Define ManualLogEntryBeforePublish hook / T215675 I introduced the ManualLogEntryBeforePublish hook that allows to inject additional tags (It's used only by MobileFronted extension).

I analyzed the code and from my understanding:

The addTags function signature is:

public static function addTags( $tags, $rc_id = null, $rev_id = null, $log_id = null, $params = null, RecentChange $rc = null ) {

And the stracktrace says:

#1 /srv/mediawiki/php-1.33.0-wmf.22/includes/logging/LogEntry.php(811): ChangeTags::addTags(array, NULL, NULL, integer)

which looks like system passes the $log_id (4th param, it's visible as integer in the stacktrace). ChangeTags verifies all params in a simple way:

		if ( !$rc_id && !$rev_id && !$log_id ) {
			throw new MWException( 'At least one of: RCID, revision ID, and log ID MUST be ' .
				'specified when adding or removing a tag from a change!' );
		}

This makes me think, that the $log_id is just simply 0 (or something that !$log_id evaluates to true in different scenarios), and that's why the system fails. Now the question is, why the $log_id is 0,
is it a problem with inserting to the database? Or is the case that someone is calling publish without inserting row first?

As a quick fix, we can introduce a check, first verify that log id exists before it calls ChangeTags::addTags(). We need to check $newId similar way as we check the $revId here https://github.com/wikimedia/mediawiki/blob/master/includes/logging/LogEntry.php#L811.

Change 498809 had a related patch set uploaded (by Pmiazga; owner: Pmiazga):
[mediawiki/core@master] Publish ManualLogEntry change tags only when $newId is present

https://gerrit.wikimedia.org/r/498809

FYI I'll be starting the 1.33.0-wmf.23 branch cut shortly. If https://gerrit.wikimedia.org/r/c/mediawiki/core/+/498809 doesn't make it in I will plan on backporting it prior to actual deployment.

@dduvall we're very close to merge. Can you give us couple more minutes, please?

@dduvall we're very close to merge. Can you give us couple more minutes, please?

Of course! To clarify, I wouldn't actually deploy without this as it's a train blocker—it would just be cherry picked prior to deployment instead of already incorporated in the new branch. I just need to start the branching process soonish as it takes a while.

@pmiazga And more importantly: thanks for the fix! :)

Change 498809 merged by jenkins-bot:
[mediawiki/core@master] Supress ChangeTags::addTags() exceptions for ManualLogEntry objects

https://gerrit.wikimedia.org/r/498809

Jdforrester-WMF lowered the priority of this task from Unbreak Now! to High.Mar 27 2019, 3:18 PM
Jdforrester-WMF subscribed.

Nominally fixed -> not UBN.

Looks like it's fixed, I don't see errors from wmf.23 branch, but let's keep it open for a couple more days to make sure the issue is fixed.

Is there an alternative method to publish an entry without revId nor logId? With .23 on group1 I now see some logspam (link) from AbuseFilter, which does a ->publish(0, dest). However, AbuseLog is not on Special:Log and thus doesn't have a logId, while using publish() is useful as it allows to mirror filter hits to RC.

Is there an alternative method to publish an entry without revId nor logId? With .23 on group1 I now see some logspam (link) from AbuseFilter, which does a ->publish(0, dest). However, AbuseLog is not on Special:Log and thus doesn't have a logId, while using publish() is useful as it allows to mirror filter hits to RC.

Tags can be associated by RCID as well. Only one of RCID, Rev ID, or Log ID is required.

I'm not sure I understand the concept of a LogEntry with id=0, but my guess is that you want to have a recent changes entry for a log event that is not stored under Special:Log. That seems reasonable. But then then why are they missing an RCID?

@Krinkle Thanks! I missed the RCID part, and IIRC we do have an RCID there. Tomorrow I'll investigate further.
And yes, we want a RC entry for an event not in Special:Log.

@Daimona definitely there is a configuration problem with AbuseFilter. If you have the RCID, then $wgAbuseFilterNotifications has to be set to rc or rcandudp. If it's set to udp, then tags are not applied to the RecentChange.

The only thing that happens when you do ManualLogEntry::publish(0, 'udp') is $rc->notifyFeeds() which you can call from AbuseFiter directly. There is no need to call ::publish in this scenario.

I checked the wmf-config, and the wgAbuseFilterNotifications is set to udp, or to false for couple wikis. The second param of ManualLogEntry::publish() cannot be false. The AbuseFilter code is definitely funky (this line: https://github.com/wikimedia/mediawiki-extensions-AbuseFilter/blob/72c2be7a18edd5e8b27f2de315e188d9485bb82b/includes/AbuseFilter.php#L1461). It not only passes 0 as a first param, but for some wikis it passes false for second param (which is also unexpected).

Do you want me to create a phab ticket for that?

@pmiazga Thanks! Well, actually the if above will prevent false to be passed as second parameter, but the ID being 0 is of course a thing. Later today I'll effectively check whether we have an RCID, use it if we do, and call notifyFeeds if we don't. I also think this task isn't completely a wrong place to talk about it, given that AbuseFilter seems to be the only cause of this problem per logstash.

Later today I'll effectively check whether we have an RCID, use it if we do, and call notifyFeeds if we don't.

In my understanding AbuseFilter runs before the edit is saved. Are there rules that run afterwards? The only reason I can see would indeed be to set tags...

OK so I was wrong, we don't have an ID, as we don't insert() the entry. I guess this happens because, as I said above, that part of the code is just used to mirror AbuseLog in RC, so we don't really want a duplicate in Special:Log. We're not interested in adding tags to the "mirror entry", either. Thus, I'm going to replicate what publish() does, removing the tags parts.

@daniel You are correct, and that applies to actions other than edits, too. In order to add tags, we use a static variable written before saving and read in the RecentChange_save handler, after saving.

Change 499766 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Don't publish LogEntries without ID

https://gerrit.wikimedia.org/r/499766

Nominally fixed -> not UBN.

Looks like it's fixed, I don't see errors from wmf.23 branch, but let's keep it open for a couple more days to make sure the issue is fixed.

Considering there are no new errors related to the original issue, I've removed this from last week's train blockers. If anyone disagrees, feel free to add it under this week's train task (T206678: 1.33.0-wmf.24 deployment blockers).

@Daimona the original error message is solved (now we log this error as a warning, not an exception), and looks like the AbuseFilter is the only extension that causes the ManualLogEntry::publish() to log a warning.
I created a separate ticket to fix the AbuseFilter behavior T219951: AbuseFilter shouldn't publish `udp` LogEntries with $newId=0 and I'd like to resolve this task.

Change 499766 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Don't publish LogEntries without ID

https://gerrit.wikimedia.org/r/499766

mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:07 PM