Page MenuHomePhabricator

AbuseFilter log error on fiwiki: /srv/mediawiki/php-1.34.0-wmf.5/includes/Revision.php:639 Call to a member function getId() on a non-object (null)
Closed, DuplicatePublicPRODUCTION ERROR

Description

Regression from wmf/1.34.0-wmf.5 (release notes)

Error

Request URL:
Request ID: INSERT_ID

message
Call to a member function getId() on a non-object (null)
trace
 	#0 /srv/mediawiki/php-1.34.0-wmf.5/includes/page/WikiPage.php(575): Revision->getId()
#1 /srv/mediawiki/php-1.34.0-wmf.5/includes/page/WikiPage.php(514): WikiPage->loadFromRow(stdClass, integer)
#2 /srv/mediawiki/php-1.34.0-wmf.5/includes/Storage/DerivedPageDataUpdater.php(518): WikiPage->loadPageData(integer)
#3 /srv/mediawiki/php-1.34.0-wmf.5/includes/Storage/DerivedPageDataUpdater.php(751): MediaWiki\Storage\DerivedPageDataUpdater->grabCurrentRevision()
#4 /srv/mediawiki/php-1.34.0-wmf.5/includes/page/WikiPage.php(2009): MediaWiki\Storage\DerivedPageDataUpdater->prepareContent(User, MediaWiki\Storage\RevisionSlotsUpdate, boolean)
#5 /srv/mediawiki/php-1.34.0-wmf.5/includes/page/Article.php(2689): WikiPage->prepareContentForEdit(WikitextContent, NULL, User, NULL, boolean)
#6 /srv/mediawiki/php-1.34.0-wmf.5/extensions/AbuseFilter/includes/AFComputedVariable.php(298): Article->prepareContentForEdit(WikitextContent)
#7 /srv/mediawiki/php-1.34.0-wmf.5/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(58): AFComputedVariable->compute(AbuseFilterVariableHolder)
#8 /srv/mediawiki/php-1.34.0-wmf.5/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(106): AbuseFilterVariableHolder->getVar(string)
#9 /srv/mediawiki/php-1.34.0-wmf.5/extensions/AbuseFilter/includes/api/ApiQueryAbuseLog.php(215): AbuseFilterVariableHolder->exportAllVars()
#10 /srv/mediawiki/php-1.34.0-wmf.5/includes/api/ApiQuery.php(249): ApiQueryAbuseLog->execute()
#11 /srv/mediawiki/php-1.34.0-wmf.5/includes/api/ApiMain.php(1593): ApiQuery->execute()
#12 /srv/mediawiki/php-1.34.0-wmf.5/includes/api/ApiMain.php(531): ApiMain->executeAction()
#13 /srv/mediawiki/php-1.34.0-wmf.5/includes/api/ApiMain.php(502): ApiMain->executeActionWithErrorHandling()
#14 /srv/mediawiki/php-1.34.0-wmf.5/api.php(87): ApiMain->execute()
#15 /srv/mediawiki/w/api.php(3): include(string)
#16 {main}

Impact

Mostly on fiwiki abuse filter log.

Notes

Event Timeline

Only happens on fiwiki because they have some automated process in place which scrapes AbuseLog entries and often comes across broken entries. In short, the error happens because in the past we used to store in the DB serialized instances of AFComputedVariable, which in turns includes instances of Revision etc (scary, right?). The Revision class has changed since then, and the error pops out. The proper solution is a maintenance script as devised in T213006, which in turn is blocked (at least) on T34478 and T213478. A hack was put in place at https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/AbuseFilter/+/502946/, but apparently that's not enough.

hashar added subscribers: daniel, Simetrical.

Eventually that also happen on eswiki or enwiki, albeit way less. Over 7 days:

Domain#
fi.wikipedia.org89,510
es.wiktionary.org209
en.wikipedia.org207
he.wikipedia.org2
ar.wikipedia.org1

The first hits in the logs (times are UTC):

eswiktionary2019-05-15T21:01:43
eswiktionary2019-05-15T21:42:42
eswiktionary2019-05-16T10:18:37
eswiktionary2019-05-16T10:59:07
eswiktionary2019-05-16T11:03:22

Then exceptions for fiwiki started at 2019-05-16T13:04:23

Which matches with the deployment of wmf/1.34.0-wmf.5 to fiwiki:

13:04 <hashar@deploy1001> rebuilt and synchronized wikiversions files: all wikis to 1.34.0-wmf.5

I am reopening this task, it is a regression in mediawiki/core. Most probably due to https://gerrit.wikimedia.org/r/#/c/mediawiki/core/+/507028/ / 090f6daa1b388b772a724984debf7ba287a8bebe

Looking at the stacktrace and at the amount of errors on fiwiki, I'm still convinced that it's a duplicate of T187153. At any rate, we're gonna prove or disprove it once https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/AbuseFilter/+/510725/ hits production in wmf.6.

I do not know much about MediaWiki nowadays, but the fault is in WikiPage::loadFromRow( $data, $from ) which, when given $data does:

573             // T39225: $latest may no longer match the cached latest Revision object.
574             // Double-check the ID of any cached latest Revision object for consistency.
575             if ( $this->mLastRevision && $this->mLastRevision->getId() != $this->mLatest ) {
576                 $this->mLastRevision = null;
577                 $this->mTimestamp = '';
578             }

Which leads to /srv/mediawiki/php-1.34.0-wmf.5/includes/Revision.php:639:

633     /**
634      * Get revision ID
635      *
636      * @return int|null
637      */
638     public function getId() {
639         return $this->mRecord->getId();
640     }

And mRecord is null somehow :-(

And mRecord is null somehow :-(

That is very strange, and should not be possible at all...

Have you seen T187153? If it's the same issue (and I think it is), mRecord is null because there's a Revision object serialized and stuffed into the DB which could be 10 years old now, it's pretty obvious that unserializing and using it is not going to work...

Have you seen T187153? If it's the same issue (and I think it is), mRecord is null because there's a Revision object serialized and stuffed into the DB which could be 10 years old now, it's pretty obvious that unserializing and using it is not going to work...

Eeeek. We should probably not even try to unserialize them!

Have you seen T187153? If it's the same issue (and I think it is), mRecord is null because there's a Revision object serialized and stuffed into the DB which could be 10 years old now, it's pretty obvious that unserializing and using it is not going to work...

Eeeek. We should probably not even try to unserialize them!

Heh, that's asking too much :-) As I said in T223447#5186965, there are plans to get rid of them, but the process is currently stalled. I was waiting for input on T34478 and T213478 before moving on.

Mattlom7 removed a project: User-Daimona.
Mattlom7 updated the task description. (Show Details)
Aklapper raised the priority of this task from Medium to Needs Triage.May 24 2019, 7:09 AM
Aklapper updated the task description. (Show Details)
Aklapper added a project: User-Daimona.

As expected, this was fixed by the patch for T187153, which landed in production yesterday with wmf.6 at 13:22UTC. The error rate dropped from ~475/30 mins to a flat 0 at that time.

As expected, this was fixed by the patch for T187153, which landed in production yesterday with wmf.6 at 13:22UTC. The error rate dropped from ~475/30 mins to a flat 0 at that time.

Perfect!! Thank you for the house keeping :]]]]

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