We dug into the Web request logs. All the 500s were coming from /api/rest_v1/page/related/*. Presumably the new MW version has some different output to what's used by RB, which ends up emitting a 500 error to the user.

Relevant logstash range for restbase errors during the deployed period.

https://logstash.wikimedia.org/app/kibana#/dashboard/restbase?_g=(refreshInterval:(display:Off,pause:!f,value:0),time:(from:'2020-02-13T20:12:01.335Z',mode:absolute,to:'2020-02-13T20:41:17.975Z'))&_a=(description:'',filters:!(('$state':(store:appState),meta:(alias:!n,disabled:!f,index:'logstash-*',key:_type,negate:!f,type:phrase,value:restbase),query:(match:(_type:(query:restbase))))),options:(darkTheme:!f),panels:!((col:1,id:Events-Over-Time,panelIndex:1,row:1,size_x:8,size_y:2,type:visualization),(col:9,id:Events-By-LevelPath,panelIndex:4,row:1,size_x:4,size_y:2,type:visualization),(col:1,id:e718a5c0-47be-11e7-b915-7ffb62c38d14,panelIndex:7,row:10,size_x:12,size_y:3,type:visualization),(col:1,id:'237252f0-47bf-11e7-b915-7ffb62c38d14',panelIndex:8,row:13,size_x:12,size_y:3,type:visualization),(col:1,columns:!(level,host,message),id:Channel-Events,panelIndex:9,row:3,size_x:12,size_y:7,sort:!('@timestamp',desc),type:search)),query:(query_string:(analyze_wildcard:!t,query:'*')),timeRestore:!t,title:restbase,uiState:(P-1:(vis:(legendOpen:!f))),viewMode:view)

For the given time period the CirrusSearch more_like cache, which is a second level cache (the http responses should be cached by traffic infra ) hit rate dropped from ~75% to 5%, and climbed back to ~12% over the ten minutes of deployment. The number of successfull requests doubled from ~200 to ~400, but this was not enough to handle the dramatic drop in hit rate.

Will need to investigate what about this changed, the way the cache key for these is generated is actually fairly fragile, at least when taking into account that we don't have the ability to drop and rebuild the cache live without dropping requests.

This RESTBase endpoint is pretty much wrapping Action API generator:search endpoint with a morelike query and returns the result. The logs indicate the problem is either in the Action API or in Cirrus Search. Here's the code for the request RESTbase generates: https://github.com/wikimedia/restbase/blob/master/v1/related.js#L24-L33

Essentially what has happened here is that the namespace passed to elasticsearch has changed types from a string to an integer. This changed the request, which invalidates the cache. As for best method forward, not sure. Most direct of course is to change that integer back into a string, but there isn't an obviously great place to do that.

Change 572119 had a related patch set uploaded (by EBernhardson; owner: EBernhardson):
[mediawiki/extensions/CirrusSearch@master] Force namespace filter to use strings

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

Provisional plan is to make a config change to split half the traffic to codfw and roll the train with it, then once it's stabilised point traffic back all to eqiad.

As an alternate solution, we may actually be able to drop the cache and repopulate it. There is a failover cluster matching the primary cluster in the codfw datacenter, and CirrusSearch has support to redirect classes of queries to particular clusters. We can direct all of these related articles requests to the codfw cluster, and with it not being occupied by the typical search load we may be able to serve the full request load as the cache refills.

Our daily request rate varies from ~450 to ~700 qps of related articles traffic. During the rollout eqiad served ~400 qps of that before throttling additional requests at the PoolCounter (cluster stayed healthly, we rejected requests well over typical rates). We can increase the pool counter capacity while directing related articles traffic at codfw and likely serve the full 700qps. The cache in question has a 24hr ttl, so this can all be un-done the next day.

Sounds workable. Let's co-ordinate early tomorrow.

Change 572126 had a related patch set uploaded (by EBernhardson; owner: EBernhardson):
[operations/mediawiki-config@master] cirrus: redirect more_like to codfw to rebuild query cache

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

Change 572126 merged by jenkins-bot:
[operations/mediawiki-config@master] cirrus: redirect more_like to codfw to rebuild query cache

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

Mentioned in SAL (#wikimedia-operations) [2020-02-14T00:51:50Z] <jforrester@deploy1001> Synchronized wmf-config/PoolCounterSettings.php: T245202 cirrus: Increase the pool counter limits a bit (duration: 01m 05s)

Mentioned in SAL (#wikimedia-operations) [2020-02-14T00:53:35Z] <jforrester@deploy1001> Synchronized wmf-config/InitialiseSettings.php: T245202 cirrus: Move all move_like traffic to codfw (duration: 01m 02s)

Change 572119 abandoned by EBernhardson:
Force namespace filter to use strings

Reason:
Instead shifting all more_like traffic to the codfw search cluster to support a full drop-and-rebuild of this cache.

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

Mentioned in SAL (#wikimedia-operations) [2020-02-18T17:47:21Z] <marxarelli> re-rolling wmf.19 to all wikis (T233867) with eyes particularly on (T245202)

Random data points so I can find them next time we have this issue:

• Typical peak load is 200qps or more_like
• Peak more_like at deployment on codfw was ~675qps.
• Peak search thread pool occupancy was 675. This is about 50% higher than our typical daily rate when all traffic is on one cluster.
• No pool counter rejection or search thread pool rejections reported
• p75 Latency increased from 180 to 250ms. p95 from 350ms to 550ms.
• After 30 minutes: 550qps, p75 200ms, p95 425ms. Hit rate of 25%.