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.

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

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.

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.

In T187153#5148376, @Daimona wrote:

@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:

In T187153#4857381, @gerritbot wrote:

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

(removing review tag given patch is still WIP)

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.

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?

In T187153#5885909, @Jdforrester-WMF wrote:

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.

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

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?

In T187153#6631519, @daniel wrote:

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.

I see some "temporarily catch XXX error" commits by @Daimona, should we revert them now that the script was ran?

In T187153#6678246, @Urbanecm wrote:

I see some "temporarily catch XXX error" commits by @Daimona, should we revert them now that the script was ran?

Oh, yes, I thought I had included the removal in some cleanup commits that were merged today.

Change 647123 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Remove more BC code

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

Change 647123 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Remove more BC code

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