Re: [MediaWiki-Core] Late bug escalation

Le 06/05/2014 18:56, Rob Lanphier a écrit : Ccing Faidon who provided the fix. This is rather long and is public since mediawiki-core list is publicly available. We might want a shorter postmortem on the wiki. To long, not willing to read: our MediaWiki configuration did not trust X-Forwarded-For headers sent by the media server and ended up throttling them instead of the end users. == Timeline of events == Saturday May 3rd 15:00 UTC community member Yann Forget reopened [bug 64622] (although unrelated) mentioning that thumbnails rendering fails with the error message: "Error generating thumbnail As an anti-spam measure, you are limited from performing this action too many times in a short space of time, and you have exceeded this limit. Please try again in a few minutes." Nemo Bis confirmed a few hours after that the error is widespread and impacts commons as well. That is not surprising since the thumbnails rendering infrastructure is shared among wiki projects. On Sunday May 4th, Nemo mentions some rate limiting configuration has been added for the "renderfile-nonstandard" throttle and deployed on April 21st ( https://gerrit.wikimedia.org/r/#/c/127643/ ) Tuesday May 5th 3:00 UTC Greg emits an email to the MediaWiki-core list escalating the bug report. Around 8:00 UTC I read the email and do some preliminary investigation. Since Nemo mentioned the 'renderfile-nonstandard' throttle I grep our limiter.log file to find out what is hitting the limit: $ fgrep renderfile limiter.log |cut -d\: -f4|sort|uniq -c|sort -n 378 10.64.0.168 tripped! mediawiki 405 10.64.0.167 tripped! mediawiki 476 10.64.32.92 tripped! mediawiki 498 10.64.16.150 tripped! mediawiki $ The IP are the media server frontends ms-fe1001 to ms-fe1004 which relay thumbnails generation requests on behalf of users. We want to throttle per end user client IP or username, NOT the proxies. My assumption is that the media servers do not relay the end user X-Forwarded-For header which contains the end user IP. I look at the Swift proxy rewrite.py script and find out that X-Forwarded-For seems to be handled in there. I ping Faidon and he immediately confirmed X-Forwaded-For header is properly handled by the Swift proxies via rewrite.py and suggest that the media servers are not listed in MediaWiki configuration as trusted proxies. On May 5th 9:00 UTC we add the media servers to the list of trusted proxies: https://gerrit.wikimedia.org/r/#/c/131670/2/wmf-config/squid.php,unified Additionally add a comment in Puppet configuration to remember folks to update the trusted proxy list whenever a new proxy is added: https://gerrit.wikimedia.org/r/#/c/131671/1/manifests/site.pp,unified The media servers disappear from limiter.log == how it happened == The first occurrence of a media server being tripped by renderfile-nonstandard occurs on 2014-04-29 18:04:05 Nemo detected the throttle configuration has been added to mediawiki-config on April 21st and deployed that day: https://gerrit.wikimedia.org/r/#/c/127643/ The throttle has been merged in mediawiki/core master branch on April 21st as well https://gerrit.wikimedia.org/r/126052 sha1: 4f2324fc MediaWiki change landed in 1.24wmf2 which $ git branch --remote --contains 4f2324fc gerrit/master gerrit/wmf/1.24wmf2 gerrit/wmf/1.24wmf3 The 1.24wmf2 deployed the change on April 30st 18:03: 18:03 logmsgbot: reedy rebuilt wikiversions.cdb and synchronized wikiversions files: Non wikipedias to 1.24wmf2 "Instantly" causing the media server to be throttled. == What can be improved == The throttling is handled by User->pingLimiter() which has a profile in entry point. Hence it generates a count metric in graphite as MediaWiki.User.pingLimiter.count I have generated a graph from January 1st 2014 till today and uploaded it on wikitech: https://wikitech.wikimedia.org/wiki/File:Wmfcluster-user_pinglimiter-201401… It shows an increase on March 26th which is unrelated and second increase on April 30th. 1) we might want to generate finer metrics by adding the pingLimiter() action to the wfProfileIn() call. 2) a graph in gdash and a monitoring alarm could be added whenever the rate change significantly. 3) it took us too long (3 days) to get informed about that outage though as soon as the proper folks have been made aware of it it got promptly solved. 4) the misconfiguration was hard to spot until we actually got hit by it :-/ == References == [bug 64622] https://bugzilla.wikimedia.org/64622 Trusting XFF from media servers: https://gerrit.wikimedia.org/r/131670 -- Antoine "hashar" Musso