On it

Meh, it's probably some old, corrupted row... May you please post the result of running fetchText.php with ID 850575? Thanks.

Change 533198 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Use row->afl_action instead of $vars

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

In T231542#5450720, @Daimona wrote:

Meh, it's probably some old, corrupted row... May you please post the result of running fetchText.php with ID 850575? Thanks.

hashar@mwmaint1002:~$ mwscript fetchText.php --wiki=eswiktionary 850575
<I press enter>
-1
<I press enter again>
-1

So that is not very helpful :-]]] Maybe https://es.wiktionary.org/w/index.php?oldid=850575 is relevant?

In T231542#5450927, @hashar wrote:

In T231542#5450720, @Daimona wrote:

Meh, it's probably some old, corrupted row... May you please post the result of running fetchText.php with ID 850575? Thanks.

hashar@mwmaint1002:~$ mwscript fetchText.php --wiki=eswiktionary 850575
<I press enter>
-1
<I press enter again>
-1

So that is not very helpful :-]]] Maybe https://es.wiktionary.org/w/index.php?oldid=850575 is relevant?

:O Could you please run the following via eval.php?

var_dump( AbuseFilter::loadVarDump( 'stored-text:850575' ) );

thanks.

Nicer :)

mwmaint1002:~$ mwscript shell.php --wiki=eswiktionary
Psy Shell v0.9.9 (PHP 7.2.8-1+0~20180725124257.2+stretch~1.gbp571e56 — cli) by Justin Hileman
>>> AbuseFilter::loadVarDump( 'stored-text:850575' )
=> AbuseFilterVariableHolder {#2703
     +forFilter: false,
     +mVarsVersion: 2,
   }
>>>

In T231542#5450952, @hashar wrote:

Nicer :)

Thanks :)

mwmaint1002:~$ mwscript shell.php --wiki=eswiktionary
Psy Shell v0.9.9 (PHP 7.2.8-1+0~20180725124257.2+stretch~1.gbp571e56 — cli) by Justin Hileman
>>> AbuseFilter::loadVarDump( 'stored-text:850575' )
=> AbuseFilterVariableHolder {#2703
     +forFilter: false,
     +mVarsVersion: 2,
   }
>>>

So, this is very corrupted... That's an empty object! Let me investigate further.

Apparently, loadVarDump succeeds because it just returns an empty VariableHolder if it cannot find the text row. So my next question is: what's the result of the following query?

select * from text where old_id = 850575

At this point, I know that this was a pre-existing problem involving corrupted/missing rows, and it was just exacerbated recently by adding stricter validation. Before fixing it, I'd like to know why these rows are missing, though.

Eeeek, I see lots of rows are missing in eswiktionary. See here: the first good entry is on March 10th, anything before that is empty. And I can also reproduce on itwiki! There, the cutoff seems to be between 20:07 and 20:12, 13 March. Why are text rows disappearing like that???

I do not know how to retrieve text from the external storage servers ( DB://cluster24/14696 )

In T231542#5451065, @hashar wrote:

mwmaint1002:~$ mwscript sql.php --wiki=eswiktionary
> select * from text where old_id = 850575;
stdClass Object
(
    [old_id] => 850575
    [old_namespace] => 
    [old_title] => 
    [old_text] => DB://cluster24/14696
    [old_comment] => 
    [old_user] => 
    [old_user_text] => 
    [old_timestamp] => 
    [old_minor_edit] => 
    [old_flags] => gzip,external
    [inverse_timestamp] => 
)

>

Cool, so the row is not empty.

In T231542#5451073, @hashar wrote:

I do not know how to retrieve text from the external storage servers ( DB://cluster24/14696 )

I thought fetchText would do that. But well, it's just returning -1 without a word about why it fails... And in fact, there are XXXs in the code. Given that patching fetchText and backporting could be undesirable, let's try to split it in pieces via eval/shell:

$id = SqlBlobStore::makeAddressFromTextId( 850575 );

and then put the return value in

MediaWikiServices::getInstance()->getBlobStore()->getBlob( $id );

What exception are we getting?

In T231542#5451062, @Daimona wrote:

Eeeek, I see lots of rows are missing in eswiktionary. See here: the first good entry is on March 10th, anything before that is empty. And I can also reproduce on itwiki! There, the cutoff seems to be between 20:07 and 20:12, 13 March. Why are text rows disappearing like that???

Seems to resemble 1_21-wmf.11's times. Dunno if it's just a coincidence though.

In T231542#5451131, @Daimona wrote:

Seems to resemble 1_21-wmf.11's times. Dunno if it's just a coincidence though.

It's not, wmf.11 included https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/AbuseFilter/+/42501/ which touched exactly the storage format. Although I wouldn't have expected it to break anything, given the huge amount of back-compat code, of which we should get rid as part of T213006. But well, at least the data seems to be there, so...

or P9000 :)

Change 533198 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Use row->afl_action instead of $vars

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

Little summary of what emerged by testing with @Urbanecm: everything is working fine in AF, and we get a serialized object: T231542#5451220. But then, when trying to unserialize it, we end up with an "empty" AbuseFilterVariableHolder. Not surprising, given how brittle PHP serialization is. However, if I copypaste the serialized object and try to unserialize it locally, serialization fails hard (i.e. returns false + PHP notice). Instead, if I download the gz compressed text, gzinflate it, and then unserialize it, I get the "full" object I'd expect. That's weird, huh?

This should be addressed in T213006, but first I'd like to understand what's going on...

Adding few links from debugging with @Daimona, to let anyone to help.

• gz compressed text
• GZ inflated text: P9003

In T231542#5451467, @Daimona wrote:

Little summary of what emerged by testing with @Urbanecm: everything is working fine in AF, and we get a serialized object: T231542#5451220. But then, when trying to unserialize it, we end up with an "empty" AbuseFilterVariableHolder. Not surprising, given how brittle PHP serialization is. However, if I copypaste the serialized object and try to unserialize it locally, serialization fails hard (i.e. returns false + PHP notice). Instead, if I download the gz compressed text, gzinflate it, and then unserialize it, I get the "full" object I'd expect. That's weird, huh?

This should be addressed in T213006, but first I'd like to understand what's going on...

So, there are probably various things involved... The copy/paste error could be due to encoding problems. As for the actual error, my main suspect now is: the serialized class contained in the DB had the $mVars property as public. But we made that property private a while ago (rEABF304b58d46abe159bad6d9dc61b60afc031931213). Maybe PHP7/HHVM refuses to include it in the unserialize() output? I tried some quick tests on 3v4l, and there doesn't seem to be any difference between the two, though. Does any of you know anything about such differences?
We could also try to just make the property public (with a @fixme comment linking to T213006), if that works. But we need a reliable way to test it. In the tests above, @Urbanecm discovered that, while with shell.php mVars is missing, with mwrepl it works and mVars is correctly populated.
Also note that, when viewing the link in the task description under PHP7, I don't get the AFPException, but instead:

[XWfvqgpAIHsAAEz2piIAAAAX] /wiki/Especial:RegistroAbusos/4122   Error from line 639 of /srv/mediawiki/php-1.34.0-wmf.20/includes/Revision.php: Call to a member function getId() on null

#0 /srv/mediawiki/php-1.34.0-wmf.20/includes/page/WikiPage.php(575): Revision->getId()
#1 /srv/mediawiki/php-1.34.0-wmf.20/includes/page/WikiPage.php(514): WikiPage->loadFromRow(stdClass, integer)
#2 /srv/mediawiki/php-1.34.0-wmf.20/includes/Storage/DerivedPageDataUpdater.php(524): WikiPage->loadPageData(integer)
#3 /srv/mediawiki/php-1.34.0-wmf.20/includes/Storage/DerivedPageDataUpdater.php(756): MediaWiki\Storage\DerivedPageDataUpdater->grabCurrentRevision()
#4 /srv/mediawiki/php-1.34.0-wmf.20/includes/page/WikiPage.php(2013): MediaWiki\Storage\DerivedPageDataUpdater->prepareContent(User, MediaWiki\Storage\RevisionSlotsUpdate, boolean)
#5 /srv/mediawiki/php-1.34.0-wmf.20/includes/page/Article.php(2691): WikiPage->prepareContentForEdit(WikitextContent, NULL, User, NULL, boolean)
#6 /srv/mediawiki/php-1.34.0-wmf.20/extensions/AbuseFilter/includes/AFComputedVariable.php(231): Article->prepareContentForEdit(WikitextContent)
#7 /srv/mediawiki/php-1.34.0-wmf.20/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(79): AFComputedVariable->compute(AbuseFilterVariableHolder)
#8 /srv/mediawiki/php-1.34.0-wmf.20/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php(190): AbuseFilterVariableHolder->getVar(string)
#9 /srv/mediawiki/php-1.34.0-wmf.20/extensions/AbuseFilter/includes/special/SpecialAbuseLog.php(649): AbuseFilterVariableHolder->dumpAllVars(boolean)
#10 /srv/mediawiki/php-1.34.0-wmf.20/extensions/AbuseFilter/includes/special/SpecialAbuseLog.php(130): SpecialAbuseLog->showDetails(string)
#11 /srv/mediawiki/php-1.34.0-wmf.20/includes/specialpage/SpecialPage.php(573): SpecialAbuseLog->execute(string)
#12 /srv/mediawiki/php-1.34.0-wmf.20/includes/specialpage/SpecialPageFactory.php(582): SpecialPage->run(string)
#13 /srv/mediawiki/php-1.34.0-wmf.20/includes/MediaWiki.php(296): MediaWiki\Special\SpecialPageFactory->executePath(Title, RequestContext)
#14 /srv/mediawiki/php-1.34.0-wmf.20/includes/MediaWiki.php(892): MediaWiki->performRequest()
#15 /srv/mediawiki/php-1.34.0-wmf.20/includes/MediaWiki.php(523): MediaWiki->main()
#16 /srv/mediawiki/php-1.34.0-wmf.20/index.php(42): MediaWiki->run()
#17 /srv/mediawiki/w/index.php(3): require(string)
#18 {main}

which is T187153, but at least it means that the variables are there!

TL;DR: PHP serialization's fault. Likely because of a member which was made private. The error only happens on HHVM. Solution: try to make AbuseFilterVariableHolder::$mVars public (with a @fixme comment linking to T213006), and check if it works both via web, mwrepl, and shell.php.

Change 533266 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] Make AbuseFilterVariableHolder::$mVars public again

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

Change 533267 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@wmf/1.34.0-wmf.20] Make AbuseFilterVariableHolder::$mVars public again

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

@Daimona See https://3v4l.org/7XTJj. I can reproduce this on PHP 5.4-PHP 7.1 and HHVM. Seems that in PHP 7.2 it became so that serialisation for public and private fields are interchangeable. Before that, they were encoded differently not tolerated at unserialise time.

Per a recently introduced development policy this should eventually be migrated to not rely on PHP unserialization. Possibly the fields can be stored as JSON instead, with some kind of newFromJson method that does any conversion/expansion work as-needed.

In T231542#5452057, @Krinkle wrote:

@Daimona See https://3v4l.org/7XTJj. I can reproduce this on PHP 5.4-PHP 7.1 and HHVM. Seems that in PHP 7.2 it became so that serialisation for public and private fields are interchangeable. Before that, they were encoded differently not tolerated at unserialize time.

I see, thanks. However, I still cannot explain why the field is completely absent at T231542#5450952. Running a similar 3v4l (I already closed it :-/), shows that indeed the properties would have different names/values, but there's always a property containing "mVars". Anyway, if the fix works, we can ignore whatever absurd behaviour HHVM may have, given that 1-we're gonna get rid of it anyway 2-we're also planning to get rid of these serialized rows.

Here is what I meant: https://3v4l.org/H3g3G there's always a mVars property.

In T231542#5452057, @Krinkle wrote:

Per a recently introduced development policy this should eventually be migrated to not rely on PHP unserialization. Possibly the fields can be stored as JSON instead, with some kind of newFromJson method that does any conversion/expansion work as-needed.

See https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/AbuseFilter/+/482499/ and the other changes dependent on it :) I also think that PHP serialization here is very bad, and is causing several other problems, e.g. T187153 and T187731. But we first need to cleanup the DB with a script (T213006), which in turn is blocked on T34478 and T213478, to be handled at the same time.

Change 533266 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Make AbuseFilterVariableHolder::$mVars public again

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

Change 533267 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@wmf/1.34.0-wmf.20] Make AbuseFilterVariableHolder::$mVars public again

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

Mentioned in SAL (#wikimedia-operations) [2019-08-29T18:36:36Z] <krinkle@deploy1001> Synchronized php-1.34.0-wmf.20/extensions/AbuseFilter/includes/AbuseFilterVariableHolder.php: T231542 rEABFf37f0bd50cf3 (duration: 00m 53s)

I would guess it (and other referenced tasks) is similar to T156541: BagOStuff should detect obsolete serialization or an unserialization resulting in a "wrong" object. Namely that we store a serialized object but later on the class might change and php fails to unserialize. There is also an issue with HHVM and php7.2 behaving slightly differently.

For caching, an obvious fix is to vary the cache key based on the class signature so that when a property changes visibility, the key change. But for a permanent storage (external store), I don't get any idea :\

Regardless, I am happy to see it got figured out. Thank you @Daimona , @Krinkle and @Urbanecm !