Totally random idea: are cache entries deleted after they expire?

I feel this is a cache problem, but I really cannot explain it (especially because it appeared suddenly, and not during train rollout).

Little update: this still isn't working. I tried to re-enable the filter, and the first edit was caught. I also couldn't find anything happened yesterday which could have caused this.

Another update: this still isn't working. However, I created a simple throttling filter on testwiki (https://test.wikipedia.org/wiki/Special:AbuseFilter/187) and it worked as expected. Sounds like the throttle cache key isn't getting deleted, or something like that. Given the lack of anything relevant in the SAL, may I ask if there has been some secret deployment or some cache-related maintenance operation on November 28th? Without other infos I have to assume this is related to the train, even though it happened before the train reached itwiki.

EDIT: Tested directly on itwiki with my own account, the result is the same from testwiki: everything works as expected. Now it definitely sounds like cache keys haven't been deleted. Is there a way to check for it?

I don't see anything in the SAL around that time period either.

Your suspicion that it had to do with the throttle cache key not expiring seems reasonable. The logs for that channel don't go back to the 28th, so I can't fulfill that request. I see the throttle keys for the itwiki filter you linked will begin with "itwiki:abusefilter:throttle:320:", for which I see the following log messages:

2018-11-30 13:29:33 [XAE7PQpAADsAAJH21zgAAABC] mw1264 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Got value 18 for throttle key itwiki:abusefilter:throttle:320:user:REDACTED  
2018-11-30 13:29:33 [XAE7PQpAADsAAJH21zgAAABC] mw1264 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Incremented throttle key itwiki:abusefilter:throttle:320:user:REDACTED  
2018-11-30 13:29:33 [XAE7PQpAADsAAJH21zgAAABC] mw1264 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Throttle itwiki:abusefilter:throttle:320:user:REDACTED hit value 19 -- maximum is 5.  
2018-11-30 13:29:43 [XAE7RwpAICAAAAoduiEAAAAQ] mw1330 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Got value 19 for throttle key itwiki:abusefilter:throttle:320:user:REDACTED  
2018-11-30 13:29:43 [XAE7RwpAICAAAAoduiEAAAAQ] mw1330 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Incremented throttle key itwiki:abusefilter:throttle:320:user:REDACTED  
2018-11-30 13:29:43 [XAE7RwpAICAAAAoduiEAAAAQ] mw1330 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Throttle itwiki:abusefilter:throttle:320:user:REDACTED hit value 20 -- maximum is 5.  
2018-12-02 09:28:20 [XAOltApAMFQAALhuVUkAAAAJ] mw1249 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Got value 20 for throttle key itwiki:abusefilter:throttle:320:user:REDACTED  
2018-12-02 09:28:20 [XAOltApAMFQAALhuVUkAAAAJ] mw1249 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Incremented throttle key itwiki:abusefilter:throttle:320:user:REDACTED  
2018-12-02 09:28:20 [XAOltApAMFQAALhuVUkAAAAJ] mw1249 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Throttle itwiki:abusefilter:throttle:320:user:REDACTED hit value 21 -- maximum is 5.  
2018-12-02 09:28:28 [XAOlvApAMEwAAAYdMB4AAACG] mw1241 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Got value 21 for throttle key itwiki:abusefilter:throttle:320:user:REDACTED  
2018-12-02 09:28:28 [XAOlvApAMEwAAAYdMB4AAACG] mw1241 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Incremented throttle key itwiki:abusefilter:throttle:320:user:REDACTED  
2018-12-02 09:28:28 [XAOlvApAMEwAAAYdMB4AAACG] mw1241 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Throttle itwiki:abusefilter:throttle:320:user:REDACTED hit value 22 -- maximum is 5.  
2018-12-02 09:28:48 [XAOl0ApAICEAAH6UqzcAAACA] mw1331 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Got value 22 for throttle key itwiki:abusefilter:throttle:320:user:REDACTED  
2018-12-02 09:28:48 [XAOl0ApAICEAAH6UqzcAAACA] mw1331 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Incremented throttle key itwiki:abusefilter:throttle:320:user:REDACTED  
2018-12-02 09:28:48 [XAOl0ApAICEAAH6UqzcAAACA] mw1331 itwiki 1.33.0-wmf.6 AbuseFilter DEBUG: Throttle itwiki:abusefilter:throttle:320:user:REDACTED hit value 23 -- maximum is 5.

When I poke at that key with mwrepl, it claims to have no expiry set:

hphpd> $key = 'itwiki:abusefilter:throttle:320:user:REDACTED';
hphpd> $w = Wikimedia\TestingAccessWrapper::newFromObject( ObjectCache::getMainStashInstance() );
hphpd> list( $server, $conn ) = $w->getConnection( $key );
hphpd> =$conn->get( $key )
"23"
hphpd> =$conn->ttl( $key )
-1

Since the count is currently at 23 (and it's a user trigger), I'd guess we should look at the 23rd hit back for that filter+user in abuse_filter_log to guess that the bad cache key was created on 2017-01-10. Were there any bugs active back then that would have caused the throttle key to have been created with no expiry timestamp?

If nothing else, someone could go in with mwrepl and execute ObjectCache::getMainStashInstance()->delete( $key ) for any affected keys.

I took a look, but nothing came out. The MW version at the time was 1.29.0-wmf.7 (since Jan 5th), and remained in place until Jan 19th (so no train that week). I also checked backports to wmf.7, but couldn't find anything interesting there (either in core or AbuseFilter). However, if the key was created (without expiry) on 2017-01-10, it would mean that the filter hasn't worked for almost two years, albeit having a key already set to the max value (and not being modified!); then, it resumed working with apparently no reason. This doesn't make sense! I must also note that the user in question has high edit rates, and even higher filter-hitting rates (not "hundreds" like I said yesterday, but still they hitted the filter roughly 150 times within two days), which makes scanning edits and abuselog pretty difficult.
I'm at my wits' end, and it's such a shame not to have the debug log for Nov 28th, which could have helped to understand what happened. My last raw guess is that it could partly have to do with T211101, although I don't see what may have caused ambiguity here, and it wouldn't completely explain the problem neither (not the infinite TTL at least).
My final thought is that lately I've been fixing some logic related to throttling, although I cannot see how it could have to do with this bug; maybe we could've had a situation where the throttle period wasn't correctly specified when editing the filter, and due to the lack of validation we ended up with a 0, which in turn was taken as "no expiry" (is that even possible?), but again this shouldn't be the case because throttle parameters have always been correct for that filter.
If no other information can be retrieved, then we could just go on and delete the key to get the filter back working, although I'm still a bit worried. BTW, I guess the debug log only has a lifetime of 10 days, but maybe other channels (like PHP warnings/notices/errors) have a longer one; if so, could you please check if there have been any warning due to AbuseFilter on Nov 28th around 16.30-17.00 UTC?

In T210709#4813242, @Daimona wrote:

and due to the lack of validation we ended up with a 0, which in turn was taken as "no expiry" (is that even possible?),

0, empty string, null, and false all seem to be interpreted as "no expiry". So pretty much anything that could have resulted in $ratePeriod not being correctly set would have that effect.

If no other information can be retrieved, then we could just go on and delete the key to get the filter back working, although I'm still a bit worried. BTW, I guess the debug log only has a lifetime of 10 days, but maybe other channels (like PHP warnings/notices/errors) have a longer one; if so, could you please check if there have been any warning due to AbuseFilter on Nov 28th around 16.30-17.00 UTC?

Searching log entries tagged with wiki:itwiki and containing "AbuseFilter", I see only the "cache hit" and "cache miss" messages from AbuseFilter::filterAction().

Expanding it to all wikis, there are also

• A bunch of DBPerformance warnings whining about "Expectation (masterConns <= 0)".
• A login on enwiki for someone in the "abusefilter" group.
• Two "PHP Notice: Undefined index: 1" from /srv/mediawiki/php-1.33.0-wmf.6/extensions/AbuseFilter/includes/AbuseFilter.php:932, one on dewiktionary at 16:56:04 and one on ruwiktionary at 16:56:01.

Those "Undefined index: 1" warnings on that line would have caused $ratePeriod to be null, but obviously they're on the wrong wiki to have affected your itwiki filter.

In T210709#4814340, @Daimona wrote:

In the meanwhile, I think you can safely delete the key (if you haven't already).

I haven't.

@Anomie have you perchance deleted the key? I reenabled the filter and it still doesn't work. If you did delete it, this would now be a fresh example!

I haven't deleted the key.

Oh, false hope then :/ Thanks anyway.

I deleted the key.

Or at least 1 key. No guarantee its the only key with this bug.

@Bawolff Thanks! True, although I'm unsure how they could be identified. If there's a way to find them, any key matching the pattern [a-z]+:abusefilter:throttle:[0-9]*:.* without expiry suffers from this bug. If such search isn't feasible, then another idea could be to find keys without expiry created around 10 Jan 2017.