Page MenuHomePhabricator

Log warning: Duplicate get(): "officewiki:echo:seen:message:time:{n}" fetched 2 times
Closed, ResolvedPublic

Description

Storage of echo seen-times was recently migrated from Redis, to a MultiWriteBagOStuff that wraps Redis, and a RESTBagOStuff configured for Kask. Since then, Duplicate get(): "officewiki:echo:seen:message:time:{n}" fetched 2 times, has been observed in the logs.

https://logstash.wikimedia.org/app/kibana#/doc/logstash-*/logstash-mediawiki-2019.11.01/mediawiki?id=AW4paIdPP44edBvOjoHh&_g=h@44136fa

Details

Related Gerrit Patches:
operations/mediawiki-config : masterkask-echoseen: Do not report dupes
mediawiki/core : masterHashBagOSTuff: Do not insert `false` values

Event Timeline

Eevans created this task.Nov 2 2019, 12:33 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptNov 2 2019, 12:33 AM
Eevans triaged this task as Medium priority.Nov 2 2019, 12:33 AM
Restricted Application added a project: Growth-Team. · View Herald TranscriptNov 2 2019, 8:27 AM

FTR, it's not just officewiki, and not just "*:echo:seen:message" (there's also "*:echo:seen:alert"). Based on this snapshot, it's happening at a rate of roughly 45000 times per 15 minutes, hence spamming logstash.

Eevans raised the priority of this task from Medium to High.Mon, Nov 18, 5:05 PM

Change 552257 had a related patch set uploaded (by Mobrovac; owner: Mobrovac):
[operations/mediawiki-config@master] kask-echoseen: Do not report dupes

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

mobrovac claimed this task.Thu, Nov 21, 2:05 PM
mobrovac added a subscriber: mobrovac.

The above patch silences the warning for Kask's RESTBagOStuff. This used not to be the case before the transition to MultiWriteBagOStuff because the RedisBagOStuff already had these silenced, while Kask's RESTBagOStuff did not.

However, that said, it is weird that we get this when Echo uses a CachedBagOStuff singleton which should in theory avoid this altogether. I haven't looked into it, though.

Change 552268 had a related patch set uploaded (by Mobrovac; owner: Mobrovac):
[mediawiki/core@master] HashBagOSTuff: Do not insert false values

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

mobrovac added a comment.EditedThu, Nov 21, 2:34 PM

Ok, I think I found the true culprit for these messages. The fix is in the above patch. The trick here is that it is not uncommon for an Echo's cache key to be missing from the cache (in this case, from both caches). But the way the CachedBagOStuff works is that if the in-memory cache doesn't return a value, it asks the backend for it and stores it in the in-memory one unconditionally. However, since there is a high chance that that value was false, that would create a paradox of sorts in the code whereby the in-memory bag would say it has the key, but would return false. The above patch corrects the in-memory cache behaviour so as not to store the value if it's set to false.

Change 552268 abandoned by Mobrovac:
HashBagOSTuff: Do not insert false values

Reason:
Not a good route

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

Ok, I think I found the true culprit for these messages. The fix is in the above patch. The trick here is that it is not uncommon for an Echo's cache key to be missing from the cache (in this case, from both caches). But the way the CachedBagOStuff works is that if the in-memory cache doesn't return a value, it asks the backend for it and stores it in the in-memory one unconditionally. However, since there is a high chance that that value was false, that would create a paradox of sorts in the code whereby the in-memory bag would say it has the key, but would return false. The above patch corrects the in-memory cache behaviour so as not to store the value if it's set to false.

Heh I was wrong here. CachedBagOStuff explicitly checks for $value === false && !$hash->hasKey( $key ), so the above patch was not a fix for this.

Change 552257 merged by jenkins-bot:
[operations/mediawiki-config@master] kask-echoseen: Do not report dupes

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

Mentioned in SAL (#wikimedia-operations) [2019-11-25T23:07:43Z] <urbanecm@deploy1001> Synchronized wmf-config/CommonSettings.php: SWAT: d71b0ab: kask-echoseen: Do not report dupes (T237143) (duration: 00m 53s)

mobrovac closed this task as Resolved.Tue, Nov 26, 7:36 AM