Page MenuHomePhabricator

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

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
Daimona raised the priority of this task from Medium 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".Aug 28 2019, 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

Is this fixed enough to close, or are we waiting for a "proper" fix?

Is this fixed enough to close, or are we waiting for a "proper" fix?

I'd rather wait for the proper fix, this piece of code is still very brittle.

Addshore removed a subscriber: Addshore.Feb 17 2020, 9:38 AM

Change 482499 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Add a maintenance script to clean afl_var_dump

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

Shizhao moved this task from Backlog to Extensions on the Chinese-Sites board.Jul 6 2020, 1:15 AM

Tagging with MW-1.36-release, because Article::prepareContentForEdit() should be removed in 1.36, and we can't as long as it's still used.

Putting this into the Platform Engineering inbox, since it is causing log spam, see T259180 and T259179. Seen again today on production error triage.

This is marked as "high" and "stalled". Not a good combination. What is this stalled on?

This is marked as "high" and "stalled". Not a good combination. What is this stalled on?

The running of the script, same as the other two you tagged, except this isn't shown in Phab. Will adjust.

Specifically, my understanding is that this will be fixed when the old code is deleted (T213006), which is blocked on the migration finishing (T246539); this applies to T187153, T259179, T259180, and T214196.