Page MenuHomePhabricator

Special:Abuselog throws when viewing details or examining (BadMethodCallException: Call get getId() on null)
Open, Stalled, HighPublic

Description

When I view details or examine of all items in Abuselog of Abusefilter 131 on zh.wikipedia. I get Internal error.
Ex.
Special:Abuselog/672224 : [WoJqhgpAIDEAAFY2JuoAAAAI] 2018-02-13 04:33:11: Fatal exception of type "BadMethodCallException"
Special:Abusefilter/examine/log/672224 : [WoJqrgpAIC8AAGfcNPkAAADI] 2018-02-13 04:33:51: Fatal exception of type "BadMethodCallException"

timestamp: 2018-07-17T15:23:25
exception_id: W04J7ApAME4AAKNdoBQAAAAC

BadMethodCallException : Call to a member function getId() on a non-object (null)
#0 /srv/mediawiki/php-1.32.0-wmf.12/includes/page/WikiPage.php(548): Revision->getId()
#1 /srv/mediawiki/php-1.32.0-wmf.12/includes/page/WikiPage.php(487): WikiPage->loadFromRow(stdClass, integer)
#2 /srv/mediawiki/php-1.32.0-wmf.12/includes/Storage/DerivedPageDataUpdater.php(503): WikiPage->loadPageData(integer)
#3 /srv/mediawiki/php-1.32.0-wmf.12/includes/Storage/DerivedPageDataUpdater.php(727): MediaWiki\Storage\DerivedPageDataUpdater->grabCurrentRevision()
#4 /srv/mediawiki/php-1.32.0-wmf.12/includes/page/WikiPage.php(1948): MediaWiki\Storage\DerivedPageDataUpdater->prepareContent(User, MediaWiki\Storage\RevisionSlotsUpdate, boolean)
#5 /srv/mediawiki/php-1.32.0-wmf.12/includes/page/Article.php(2471): WikiPage->prepareContentForEdit(WikitextContent, NULL, User, NULL, boolean)
#6 /srv/mediawiki/php-1.32.0-wmf.12/extensions/AbuseFilter/includes/AFComputedVariable.php(195): Article->prepareContentForEdit(WikitextContent)
#7 /srv/mediawiki/php-1.32.0-wmf.12/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(49): AFComputedVariable->compute(AbuseFilterVariableHolder)
#8 /srv/mediawiki/php-1.32.0-wmf.12/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(188): AbuseFilterVariableHolder->getVar(string)
#9 /srv/mediawiki/php-1.32.0-wmf.12/extensions/AbuseFilter/includes/Views/AbuseFilterViewExamine.php(156): AbuseFilterVariableHolder->dumpAllVars(boolean)
#10 /srv/mediawiki/php-1.32.0-wmf.12/extensions/AbuseFilter/includes/Views/AbuseFilterViewExamine.php(27): AbuseFilterViewExamine->showExaminerForLogEntry(string)
#11 /srv/mediawiki/php-1.32.0-wmf.12/extensions/AbuseFilter/includes/special/SpecialAbuseFilter.php(122): AbuseFilterViewExamine->show()
#12 /srv/mediawiki/php-1.32.0-wmf.12/includes/specialpage/SpecialPage.php(566): SpecialAbuseFilter->execute(string)
#13 /srv/mediawiki/php-1.32.0-wmf.12/includes/specialpage/SpecialPageFactory.php(569): SpecialPage->run(string)
#14 /srv/mediawiki/php-1.32.0-wmf.12/includes/MediaWiki.php(288): SpecialPageFactory::executePath(Title, RequestContext)
#15 /srv/mediawiki/php-1.32.0-wmf.12/includes/MediaWiki.php(867): MediaWiki->performRequest()
#16 /srv/mediawiki/php-1.32.0-wmf.12/includes/MediaWiki.php(524): MediaWiki->main()
#17 /srv/mediawiki/php-1.32.0-wmf.12/index.php(42): MediaWiki->run()
#18 /srv/mediawiki/w/index.php(3): include(string)
#19 {main}

Related Objects

Event Timeline

There are a very large number of changes, so older changes are hidden. Show Older Changes

The report from T207545 identified an instance from en.wikipedia.org (first time I think, previously was zh.wikipedia.org):

exception_id: W8s79wpAADsAAFlsN8wAAACW
exception_url: /wiki/Special:AbuseLog/7343365 [restricted]

> BadMethodCallException: Call to a member function getId() on a non-object (null)

#0 /srv/mediawiki/php-1.32.0-wmf.26/includes/Storage/DerivedPageDataUpdater.php(538): Revision->getId()
#1 /srv/mediawiki/php-1.32.0-wmf.26/includes/Storage/DerivedPageDataUpdater.php(750): MediaWiki\Storage\DerivedPageDataUpdater->grabCurrentRevision()
#2 /srv/mediawiki/php-1.32.0-wmf.26/includes/page/WikiPage.php(1981): MediaWiki\Storage\DerivedPageDataUpdater->prepareContent(User, MediaWiki\Storage\RevisionSlotsUpdate, boolean)
#3 /srv/mediawiki/php-1.32.0-wmf.26/includes/page/Article.php(2685): WikiPage->prepareContentForEdit(WikitextContent, NULL, User, NULL, boolean)
#4 /srv/mediawiki/php-1.32.0-wmf.26/extensions/AbuseFilter/includes/AFComputedVariable.php(214): Article->prepareContentForEdit(WikitextContent)
#5 /srv/mediawiki/php-1.32.0-wmf.26/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(60): AFComputedVariable->compute(AbuseFilterVariableHolder)
#6 /srv/mediawiki/php-1.32.0-wmf.26/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(193): AbuseFilterVariableHolder->getVar(string)
#7 /srv/mediawiki/php-1.32.0-wmf.26/extensions/AbuseFilter/includes/special/SpecialAbuseLog.php(564): AbuseFilterVariableHolder->dumpAllVars(boolean)
#8 /srv/mediawiki/php-1.32.0-wmf.26/extensions/AbuseFilter/includes/special/SpecialAbuseLog.php(108): SpecialAbuseLog->showDetails(string)
#9 /srv/mediawiki/php-1.32.0-wmf.26/includes/specialpage/SpecialPage.php(569): SpecialAbuseLog->execute(string)
#10 /srv/mediawiki/php-1.32.0-wmf.26/includes/specialpage/SpecialPageFactory.php(568): SpecialPage->run(string)
#11 /srv/mediawiki/php-1.32.0-wmf.26/includes/MediaWiki.php(288): MediaWiki\Special\SpecialPageFactory->executePath(Title, RequestContext)
#12 /srv/mediawiki/php-1.32.0-wmf.26/includes/MediaWiki.php(860): MediaWiki->performRequest()
#13 /srv/mediawiki/php-1.32.0-wmf.26/includes/MediaWiki.php(517): MediaWiki->main()
#14 /srv/mediawiki/php-1.32.0-wmf.26/index.php(42): MediaWiki->run()
#15 /srv/mediawiki/w/index.php(3): include(string)
#16 {main}
bd808 added a subscriber: bd808.

From T212352: Fatal error from https://en.wikipedia.org/wiki/Special:AbuseLog/8229629:

[XBrChQpAME8AAKEkZUIAAABU] 2018-12-19 22:13:25: Fatal exception of type "BadMethodCallException"

Error log output:

[XBrChQpAME8AAKEkZUIAAABU] /wiki/Special:AbuseLog/8229629   BadMethodCallException from line 652 of /srv/mediawiki/php-1.33.0-wmf.8/includes/Revision.php: Call to a member function getId() on a non-object (null)
#0 /srv/mediawiki/php-1.33.0-wmf.8/includes/page/WikiPage.php(565): Revision->getId()
#1 /srv/mediawiki/php-1.33.0-wmf.8/includes/page/WikiPage.php(504): WikiPage->loadFromRow(stdClass, integer)
#2 /srv/mediawiki/php-1.33.0-wmf.8/includes/Storage/DerivedPageDataUpdater.php(515): WikiPage->loadPageData(integer)
#3 /srv/mediawiki/php-1.33.0-wmf.8/includes/Storage/DerivedPageDataUpdater.php(748): MediaWiki\Storage\DerivedPageDataUpdater->grabCurrentRevision()
#4 /srv/mediawiki/php-1.33.0-wmf.8/includes/page/WikiPage.php(1998): MediaWiki\Storage\DerivedPageDataUpdater->prepareContent(User, MediaWiki\Storage\RevisionSlotsUpdate, boolean)
#5 /srv/mediawiki/php-1.33.0-wmf.8/includes/page/Article.php(2691): WikiPage->prepareContentForEdit(WikitextContent, NULL, User, NULL, boolean)
#6 /srv/mediawiki/php-1.33.0-wmf.8/extensions/AbuseFilter/includes/AFComputedVariable.php(216): Article->prepareContentForEdit(WikitextContent)
#7 /srv/mediawiki/php-1.33.0-wmf.8/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(60): AFComputedVariable->compute(AbuseFilterVariableHolder)
#8 /srv/mediawiki/php-1.33.0-wmf.8/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(193): AbuseFilterVariableHolder->getVar(string)
#9 /srv/mediawiki/php-1.33.0-wmf.8/extensions/AbuseFilter/includes/special/SpecialAbuseLog.php(564): AbuseFilterVariableHolder->dumpAllVars(boolean)
#10 /srv/mediawiki/php-1.33.0-wmf.8/extensions/AbuseFilter/includes/special/SpecialAbuseLog.php(108): SpecialAbuseLog->showDetails(string)
#11 /srv/mediawiki/php-1.33.0-wmf.8/includes/specialpage/SpecialPage.php(569): SpecialAbuseLog->execute(string)
#12 /srv/mediawiki/php-1.33.0-wmf.8/includes/specialpage/SpecialPageFactory.php(558): SpecialPage->run(string)
#13 /srv/mediawiki/php-1.33.0-wmf.8/includes/MediaWiki.php(288): MediaWiki\Special\SpecialPageFactory->executePath(Title, RequestContext)
#14 /srv/mediawiki/php-1.33.0-wmf.8/includes/MediaWiki.php(862): MediaWiki->performRequest()
#15 /srv/mediawiki/php-1.33.0-wmf.8/includes/MediaWiki.php(517): MediaWiki->main()
#16 /srv/mediawiki/php-1.33.0-wmf.8/index.php(42): MediaWiki->run()
#17 /srv/mediawiki/w/index.php(3): include(string)
#18 {main}

It should not be possible for $this->mRecord to be null in line 652 of /srv/mediawiki/php-1.33.0-wmf.8/includes/Revision.php. I made a patch that should help us to find out how it does become null.

Change 481014 had a related patch set uploaded (by Daniel Kinzler; owner: Daniel Kinzler):
[mediawiki/core@master] Assert that $mRecord is never null in Revision.

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

Change 481014 merged by jenkins-bot:
[mediawiki/core@master] Revision: Assert that $mRecord is never null in Revision

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

Change 482499 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Add a maintenance script to clean afl_var_dump

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

Daimona claimed this task.Jan 6 2019, 1:56 PM
Daimona moved this task from Future to Under review on the User-Daimona board.
demon removed a subscriber: demon.Feb 19 2019, 10:36 AM
Daimona raised the priority of this task from Normal to High.Mar 17 2019, 3:09 PM
Daimona merged a task: Restricted Task.
Daimona added subscribers: elukey, 4shadoww, Andrew and 2 others.

This is hitting us over and over.

Again a ton of exceptions registered from 2019-03-22 ~21 UTC:

#0 /srv/mediawiki/php-1.33.0-wmf.22/includes/page/WikiPage.php(575): Revision->getId()
#1 /srv/mediawiki/php-1.33.0-wmf.22/includes/page/WikiPage.php(514): WikiPage->loadFromRow(stdClass, integer)
#2 /srv/mediawiki/php-1.33.0-wmf.22/includes/Storage/DerivedPageDataUpdater.php(518): WikiPage->loadPageData(integer)
#3 /srv/mediawiki/php-1.33.0-wmf.22/includes/Storage/DerivedPageDataUpdater.php(751): MediaWiki\Storage\DerivedPageDataUpdater->grabCurrentRevision()
#4 /srv/mediawiki/php-1.33.0-wmf.22/includes/page/WikiPage.php(2009): MediaWiki\Storage\DerivedPageDataUpdater->prepareContent(User, MediaWiki\Storage\RevisionSlotsUpdate, boolean)
#5 /srv/mediawiki/php-1.33.0-wmf.22/extensions/AbuseFilter/includes/AFComputedVariable.php(216): WikiPage->prepareContentForEdit(WikitextContent)
#6 /srv/mediawiki/php-1.33.0-wmf.22/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(58): AFComputedVariable->compute(AbuseFilterVariableHolder)
#7 /srv/mediawiki/php-1.33.0-wmf.22/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(106): AbuseFilterVariableHolder->getVar(string)
#8 /srv/mediawiki/php-1.33.0-wmf.22/extensions/AbuseFilter/includes/api/ApiQueryAbuseLog.php(218): AbuseFilterVariableHolder->exportAllVars()
#9 /srv/mediawiki/php-1.33.0-wmf.22/includes/api/ApiQuery.php(249): ApiQueryAbuseLog->execute()
#10 /srv/mediawiki/php-1.33.0-wmf.22/includes/api/ApiMain.php(1595): ApiQuery->execute()
#11 /srv/mediawiki/php-1.33.0-wmf.22/includes/api/ApiMain.php(531): ApiMain->executeAction()
#12 /srv/mediawiki/php-1.33.0-wmf.22/includes/api/ApiMain.php(502): ApiMain->executeActionWithErrorHandling()
#13 /srv/mediawiki/php-1.33.0-wmf.22/api.php(87): ApiMain->execute()
#14 /srv/mediawiki/w/api.php(3): include(string)
#15 {main}

Well, the maintscript is on gerrit. However, given that it'll touch many rows, I want to include there any maintenance that we need to perform on the abuse_filter_log table. Currently, it's blocked on deciding what to do with T213478 and T34478. If someone could please take a look, it'd be great.

@Daimona didn't mean to rush anybody, just added a comment as FYI for the task if needed! Thanks for the work :)

@elukey I didn't read it like that :-) Although, actually, this task deserves some attention, as it's really happening very often. Mine above was just a quick overview of the situation.

Change 482499 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] [WIP] Add a maintenance script to clean afl_var_dump

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

I don't think this should be a train blocker: it was discovered in 2018 and only affects some old entries. Nevertheless, it's really high priority. Last weeks, the spike on logstash was likely caused by a bot or something like that mass-requesting corrupted abuselog entries. I cannot check right now if that's still true, though.

zeljkofilipin raised the priority of this task from High to Unbreak Now!.Apr 10 2019, 3:20 PM
zeljkofilipin added a subscriber: zeljkofilipin.

Train blockers are UBN. If you don't think this is blocking the train, remove the parent task and change priority.

Restricted Application added a subscriber: TerraCodes. · View Herald TranscriptApr 10 2019, 3:20 PM
Daimona changed the task status from Open to Stalled.Apr 10 2019, 3:21 PM
Daimona lowered the priority of this task from Unbreak Now! to High.

@zeljkofilipin Thanks for the heads-up, per my comment above this is not a TB IMHO. Actually, this is blocked on T34478 and T213478.

If we can't solve the root problem can we at least clean up the log spam? Log spam IS a train blocker.

@mmodell I guess we do, although I don't think it's worth doing anything beyond displaying an error instead of throwing. Also, this logspam is happening since at least one year, so it's a bit late to recognize it as train blocker.

At any rate, looking at Logstash I see that it's still due to that "pseudo-bot" I noticed last week. Maybe understanding where all of those requests come from and notifying the requester would already help?

Displaying an error instead of throwing sounds like exactly the right solution to me. The log spam is intermittent but that causes confusion and uncertainty when it happens around the time of a deployment.

Change 502946 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Temporarily catch BadMethodCallException when computing _links vars

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

Instead of displaying an error, I just made it so that _links variables aren't computed for faulty entries.
Nevertheless, I hope to get the root cause solved soon. Not only for this task, but also for related ones (listed in commit message).

Change 502946 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Temporarily catch BadMethodCallException when computing _links vars

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

jcrespo added a subscriber: jcrespo.

Based on T187153#5101883 and the rate at https://logstash.wikimedia.org/goto/c930467fddcf4aaa4d4c0f8f00838498 lots of hits of this on fiwiki right now. The logging is the blocker issue, not the actual problem.

Yes, that's the "pseudobot" I mentioned in T187153#5101909 and the comment above. Something on fiwiki is mass-requesting abuselog entries since weeks. Anyway, IMHO having it logged as warning (and out of the exception channel) should make it less noisy... If not, we can safely remove the logging, although the underlying issue should still have high priority.

aborrero removed a subscriber: aborrero.Apr 29 2019, 8:23 AM

This is currently the largest producers of errors in logstash. It doesn't sound like this is actually anything to be concerned about, but fixing logging would be nice since it looks like 3 separate train deploys have been worried enough to comment on this task.

@thcipriani What would you suggest? Decreasing the log level to info?
IMHO, from a generic POV this caught exception should be logged as warning. However, given that some bot is flooding logs with it, and that apparently the underlying issue won't be fixed anytime soon, we can certainly make it less scary.

@thcipriani What would you suggest?

Fixing AF to not use serialisation of PHP for long-term storage would be significantly better than hiding the problem in a lower-priority log.

@Jdforrester-WMF I completely agree, there are plenty of reasons to do that. However, it won't be quick. Code for it is already on gerrit (see T213006), however I'm currently waiting for input on T34478 and T213478. And the code needs review of course.

Change 510725 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Temporarily catch another BadMethodCallException

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

Change 510725 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Temporarily catch another BadMethodCallException

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

For the record, the remaining patch is this one:

[mediawiki/extensions/AbuseFilter@master] Add a maintenance script to clean afl_var_dump
https://gerrit.wikimedia.org/r/482499

brennen added a subscriber: brennen.Aug 6 2019, 7:37 PM

Several of what I believe is the same issue logged in the last hour:

[XUnSXApAADgAABH1xD4AAACB] /wiki/Special:AbuseLog/6978854   Error from line 639 of /srv/mediawiki/php-1.34.0-wmf.16/includes/Revision.php: Call to a member function getId() on null
#0 /srv/mediawiki/php-1.34.0-wmf.16/includes/Storage/DerivedPageDataUpdater.php(530): Revision->getId()
#1 /srv/mediawiki/php-1.34.0-wmf.16/includes/Storage/DerivedPageDataUpdater.php(756): MediaWiki\Storage\DerivedPageDataUpdater->grabCurrentRevision()
#2 /srv/mediawiki/php-1.34.0-wmf.16/includes/page/WikiPage.php(2006): MediaWiki\Storage\DerivedPageDataUpdater->prepareContent(User, MediaWiki\Storage\RevisionSlotsUpdate, boolean)
#3 /srv/mediawiki/php-1.34.0-wmf.16/includes/page/Article.php(2691): WikiPage->prepareContentForEdit(WikitextContent, NULL, User, NULL, boolean)
#4 /srv/mediawiki/php-1.34.0-wmf.16/extensions/AbuseFilter/includes/AFComputedVariable.php(226): Article->prepareContentForEdit(WikitextContent)
#5 /srv/mediawiki/php-1.34.0-wmf.16/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(79): AFComputedVariable->compute(AbuseFilterVariableHolder)
#6 /srv/mediawiki/php-1.34.0-wmf.16/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(192): AbuseFilterVariableHolder->getVar(string)
#7 /srv/mediawiki/php-1.34.0-wmf.16/extensions/AbuseFilter/includes/special/SpecialAbuseLog.php(641): AbuseFilterVariableHolder->dumpAllVars(boolean)
#8 /srv/mediawiki/php-1.34.0-wmf.16/extensions/AbuseFilter/includes/special/SpecialAbuseLog.php(124): SpecialAbuseLog->showDetails(string)
#9 /srv/mediawiki/php-1.34.0-wmf.16/includes/specialpage/SpecialPage.php(571): SpecialAbuseLog->execute(string)
#10 /srv/mediawiki/php-1.34.0-wmf.16/includes/specialpage/SpecialPageFactory.php(581): SpecialPage->run(string)
#11 /srv/mediawiki/php-1.34.0-wmf.16/includes/MediaWiki.php(296): MediaWiki\Special\SpecialPageFactory->executePath(Title, RequestContext)
#12 /srv/mediawiki/php-1.34.0-wmf.16/includes/MediaWiki.php(892): MediaWiki->performRequest()
#13 /srv/mediawiki/php-1.34.0-wmf.16/includes/MediaWiki.php(523): MediaWiki->main()
#14 /srv/mediawiki/php-1.34.0-wmf.16/index.php(42): MediaWiki->run()
#15 /srv/mediawiki/w/index.php(3): require(string)
#16 {main}

From low volume of exceptions, comments on this issue, and being thrown from a wmf.16 path, I assume not relevant to current train, but it did make me nervous due to timing.

We fixed it by catching an exception, but PHP7 treats it as Error (AFAICS), which isn't caught in our code.
We could add catch branches for Error's, although there's been no progress with the long-term solution, and I think this error will show up more and more frequently as the % of PHP7 servers is increased.

Krinkle removed a subscriber: Krinkle.Aug 21 2019, 2:32 PM
hashar removed a subscriber: hashar.Aug 22 2019, 6:44 AM
mmodell changed the subtype of this task from "Task" to "Production Error".Wed, Aug 28, 11:09 PM

Change 533704 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Also catch Error in the hacky workaround for bad rows

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

Change 533704 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Also catch Error in the hacky workaround for bad rows

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