[11:33:54] <_joe_>	 ema, vgutierrez users reporting TLS errors starting today on #wikimedia-tech
[11:34:03] <_joe_>	 can you please join?
[13:26:29] <paravoid>	 Waiting:
[13:26:29] <paravoid>	 9715 ms
[13:26:32] <paravoid>	 while loading WP
[13:26:36] <paravoid>	 from here, at home
[13:27:01] <paravoid>	 in interview right now, but seems problematic and potentially correlated with the above reports
[13:27:06] <paravoid>	 ema, vgutierrez ^
[13:27:22] <vgutierrez>	 :?
[13:27:32] <paravoid>	 loading en.wp takes 10 seconds here
[13:27:49] <vgutierrez>	 ack, could you check the cp server that's assigned to your IP?
[13:27:55] <paravoid>	 and network-wise (traceroute etc.) looks fine
[13:27:57] <vgutierrez>	 x-cache header should point it out
[13:28:53] <paravoid>	 cp1087 pass, cp3032 pass, cp3032 pass
[13:29:08] <paravoid>	 server: mw1253.eqiad.wmnet
[13:29:11] <vgutierrez>	 thx :)
[13:34:56] <vgutierrez>	 paravoid: is it a persistent issue? cp3032 got upgraded ~50 minutes ago
[13:35:03] <paravoid>	 it is
[13:35:16] <paravoid>	 (still in interview)
[13:35:23] <vgutierrez>	 ok sorry
[13:36:10] <paravoid>	 12173 ms now
[13:44:58] <vgutierrez>	 seeing that's persistent for you.. I'm going to downgrade cp3032 and check if that helps
[13:45:11] <vgutierrez>	 but it doesn't look good :_)
[14:01:55] <paravoid>	 ok, done
[14:02:24] <paravoid>	 what's the current status?
[14:02:55] <paravoid>	 vgutierrez: ^
[14:48:10] <_joe_>	 Krinkle is not here though
[14:50:34] <Krinkle>	 _joe_: o/
[14:50:39] <paravoid>	 hey
[14:50:49] <paravoid>	 so a few users have been complaining of slowness in #-tech
[14:50:59] <_joe_>	 so, some users, and just some users, among which paravoid, see pages consistently slow
[14:51:01] <cdanis>	 so we have a small fraction of users seeing a very high Backend-Timing (10+ seconds), reproducible on mwdebug with profiles on
[14:51:03] <paravoid>	 and I experienced it myself, and I've been trying to troubleshoot
[14:51:18] <cdanis>	 https://performance.wikimedia.org/xhgui/run/view?id=5d541e293f3dfa731b8c5810
[14:51:21] <paravoid>	 I get ~8-9s consistently for one particular page ( https://en.wikipedia.org/wiki/Greece ), and as a high as 15s
[14:51:22] <_joe_>	 looking at profile data, I think it's that for those users we re-pare the pages
[14:51:40] <_joe_>	 paravoid: all pages or just some?
[14:51:43] <paravoid>	 the profiling one took 29.9s, and timed out
[14:51:53] <paravoid>	 just this one (Greece) is the one I've reproduced it with
[14:52:13] <_joe_>	 try the obama page?
[14:52:46] <_joe_>	 Krinkle: normal profile: https://performance.wikimedia.org/xhgui/run/view?id=5d541ead3f3dfa731b00e268
[14:52:59] <_joe_>	 profile when ran by paravoid https://performance.wikimedia.org/xhgui/run/view?id=5d541e293f3dfa731b8c5810
[14:53:12] <paravoid>	 also from that profiling run: https://tty.gr/s/enwiki-greece-timeout.png
[14:53:35] <_joe_>	 that's probably mwdebug being awesomely underpowered
[14:53:48] <_joe_>	 my fault then :)
[14:54:00] <bblack>	 we're going to re-upgrade cp3032 nginx btw, since it was the only downgraded one in the fleet and doesn't seem to be causative
[14:54:40] <paravoid>	 Krinkle: another data point is that I can reproduce with just -H Cookie: enwikiUserName= enwikiUserID= centralauth_User= centralauth_Token= enwikiSession= centralauth_Session= and nothing else
[14:54:41] <_joe_>	 the point is - it shouldn't be re-parsed in the first place
[14:56:20] <Krinkle>	 I'm looking at some graphs
[14:56:30] <Krinkle>	 https://grafana.wikimedia.org/d/000000580/apache-backend-timing?orgId=1
[14:57:39] <_joe_>	 Krinkle: if as I think this is limited to some users, it's probably not noticeable much there
[14:57:51] <Krinkle>	 https://grafana.wikimedia.org/d/000000038/navigation-timing-by-platform?refresh=5m&orgId=1&var-metric=responseStart&var-platform=desktop&var-users=authenticated
[14:58:30] <Krinkle>	 https://grafana.wikimedia.org/d/000000106/parser-cache?orgId=1&from=now-24h&to=now
[14:58:32] <paravoid>	 are you looking at graphs to assess impact?
[14:58:41] <Krinkle>	 Yes, and also for possible clues to narrow it down
[14:58:59] <bblack>	 btw there's a sync-wikiversions entry there on the graph at 13:31.  I thought I didn't see any deploys in ops logs
[14:59:21] <cdanis>	 those graphs are yet to render for me
[14:59:41] <cdanis>	 bblack: the metrics from the appservers began to be elevated at 12:54 or so
[14:59:43] <Krinkle>	 It seems latest Chrome has a problem with grafana, they keep locking my laptop completely
[14:59:45] <Krinkle>	 using Firefox instead
[15:00:04] <cdanis>	 https://grafana.wikimedia.org/d/RIA1lzDZk/application-servers-red-dashboard?panelId=10&fullscreen&edit&orgId=1&from=now-6h&to=now
[15:00:30] <Krinkle>	 That increase, cdanis , aligns with the drop in parser cache
[15:00:30] <Krinkle>	 https://grafana.wikimedia.org/d/000000106/parser-cache?panelId=3&fullscreen&orgId=1&from=now-2d&to=now
[15:00:38] <Krinkle>	 which underwent a sharp drop for the first time in several days
[15:00:40] <Krinkle>	 unsure why
[15:00:52] <cdanis>	 parsercache disk free space?
[15:01:07] <Krinkle>	 oh, it's inversed, ugh
[15:01:11] <Krinkle>	 thouhgt it was space used
[15:01:34] <cdanis>	 pc hit rate did go down some
[15:01:41] <bblack>	 I have no idea if related, but in the interest of highlighting timing correlations:
[15:01:46] <bblack>	 12:24 < James_F|Away> !log We're going to try making a new wiki. T212881
[15:01:46] <stashbot>	 T212881: addWiki.php broken creating ES tables - https://phabricator.wikimedia.org/T212881
[15:01:49] <cdanis>	 it seems more like a symptom though
[15:01:56] <bblack>	 12:47 < James_F> !log <sadtrombone> Wiki creation is still not working correctly, unfortunately.
[15:02:20] <bblack>	 13:50 < James_F> (We're still testing in prod, sorry anyone that wants to do something.)
[15:02:44] <James_F>	 Yeah, sorry, deploys all done.
[15:03:06] <bblack>	 and then as part of that: https://phabricator.wikimedia.org/T212881 went out around 13:50
[15:03:19] <bblack>	 or something
[15:03:23] <bblack>	 some patch referencing that
[15:03:23] * James_F looks at Reedy.
[15:03:40] <paravoid>	 ok, stupid question but... did anyone check logstash for anything out of the ordinary?
[15:03:56] <cdanis>	 paravoid: I quickly glanced and nothing stood out, but I'd welcome others to do so
[15:04:13] <_joe_>	 I did as well earlier for unrelated reasons
[15:05:13] <_joe_>	 it's pretty clear imho that we're considering parsercache invalid for some users
[15:05:27] <_joe_>	 paravoid: do you have a specific language setting for your user?
[15:05:32] <paravoid>	 no
[15:05:44] <Krinkle>	 yeah, nothing stands out at logstahs/mediawiki-errors. both with and without php timeouts included no spike
[15:05:45] <_joe_>	 I hoped a non-latin language was in play :/
[15:06:25] <_joe_>	 paravoid: I would be tempted to suggest to log out / log in
[15:06:27] <Krinkle>	 The parser cache miss category did not go up for rejection/invalid.
[15:06:30] <Krinkle>	 It only went up for expired
[15:06:42] <_joe_>	 or maybe log in form a private session
[15:06:58] <_joe_>	 and see if the problem persists
[15:07:01] <Krinkle>	 and some for absent.
[15:07:18] <Krinkle>	 So that might suggest a bulk of content just expired all at once, possibly due to being populated around the same time N days in the past?
[15:07:26] <paravoid>	 I think it'd be better not to, as to have someone with a reproducible case :)
[15:07:33] <Krinkle>	 That doesn't connect with the curl example people mentioned earlier though
[15:07:41] <cdanis>	 paravoid: you could log in again in an incognito window?
[15:07:43] <paravoid>	 it's 100% reproducible here fwiw
[15:07:54] <Krinkle>	 paravoid: can you show again which one?
[15:07:58] <paravoid>	 which one what?
[15:08:04] <Krinkle>	 the repro case you are using and how
[15:08:08] <_joe_>	 ok so
[15:08:49] <Krinkle>	 I'd look for logstash under the hostname of the server that served the request (non-debug), and maybe also via requestId.
[15:08:54] <paravoid>	 curl -vv 'https://en.wikipedia.org/wiki/Greece' -H 'Cookie: enwikiUserName=... enwikiUserID=...; centralauth_User=...; centralauth_Token=...; enwikiSession=...; centralauth_Session=...' 2>&1 |grep backend-timing
[15:08:58] <paravoid>	 < backend-timing: D=10822692 t=1565795317648302
[15:09:06] <paravoid>	 multiple MWs
[15:09:06] <_joe_>	 I just logged in in a private browser window, and I cannot reproduce the problem
[15:09:33] <_joe_>	 paravoid: can you try to log in from another session and see if the problem is tied to your session or to your user?
[15:10:24] <paravoid>	 just did, still reproducible from incognito
[15:10:28] <jynus>	 https://grafana.wikimedia.org/d/000000278/mysql-aggregated?orgId=1&from=1565786732399&to=1565801943823&var-dc=eqiad%20prometheus%2Fops&var-group=core&var-shard=es1&var-shard=es3&var-role=All&panelId=8&fullscreen
[15:10:31] <_joe_>	 wtf
[15:10:32] <Krinkle>	 I'm getting a very quick response with that example paravoid
[15:10:33] <Krinkle>	 < server: mw1323.eqiad.wmnet
[15:10:34] <Krinkle>	 < backend-timing: D=237033 t=1565795372190859
[15:10:34] <Krinkle>	 < date: Wed, 14 Aug 2019 15:09:32 GMT
[15:10:34] <Krinkle>	 < x-cache: cp1087 pass, cp3042 pass, cp3030 pass
[15:10:43] <Krinkle>	 less than a second
[15:10:47] <jynus>	 ^this means contents is being retrieved at high speed since 15
[15:10:53] <paravoid>	 Krinkle: I know, everyone else is, but note that we also have multiple people in #-tech also saying they're experiencing that kind of issue
[15:11:03] <jynus>	 which means parsercache is not working as it should
[15:11:08] <Krinkle>	 paravoid: which server are you hitting?
[15:11:12] <Krinkle>	 maybe some kind of IP sharding?
[15:11:15] <_joe_>	 jynus: or well that it's not being used
[15:11:20] <jynus>	 yeah, that
[15:11:23] <paravoid>	 Krinkle: all of them I think, it even was reproducible in mwdebug
[15:11:23] <_joe_>	 Krinkle: multiple backends
[15:11:30] <Krinkle>	 Sounds like it would be network related in that case maybe? not MW. If its consistent for you on multiple app servers but not for me e.g.
[15:11:40] <Krinkle>	 right?
[15:11:41] <jynus>	 basically, something is bad at normal cache workflow
[15:11:42] <_joe_>	 Krinkle: those are backend timings
[15:11:42] <paravoid>	 Krinkle: backend-timing is MW-set
[15:11:47] <cdanis>	 no I think it is something strange about specific user sessions
[15:12:02] <cdanis>	 Backend-Timing comes from the Apache directly in front of the appserver, Krinkle, it's basically Apache-measured PHP TTFB
[15:12:06] <_joe_>	 cdanis: users, we verified paravoid can reproduce
[15:12:07] <Krinkle>	 paravoid: are you using literal ... or using an actual session?
[15:12:14] <paravoid>	 an actual session, my session
[15:12:20] <jynus>	 strangelly, it doesn't happen on es2, only on es1 and es3
[15:12:25] <paravoid>	 for all of those "..." values
[15:12:37] <_joe_>	 jynus: uh, well, that's indeed very strange
[15:12:58] <jynus>	 cdanis: was something related to dbctl deployed at 15?
[15:13:00] <Krinkle>	 paravoid: php7?
[15:13:10] <paravoid>	 no
[15:13:14] <Krinkle>	 I guess not if using CURL without cookies
[15:13:22] <_joe_>	 Krinkle: it shows up independently of the engine
[15:13:23] <paravoid>	 correct
[15:13:29] <cdanis>	 jynus: no
[15:13:51] <jynus>	 I don't see anything relevant on sal
[15:13:51] <cdanis>	 jynus: dbctl still does not touch es or parsercache settings, and all dbctl commits go to SAL
[15:14:10] <jynus>	 I know, maybe it started to do so :-D, but there is nothing on sal
[15:14:11] <Krinkle>	 OK. now it's slow for me as well on that page, paravoid , using curl and my actual session
[15:14:17] <Krinkle>	 ~ 11 seconds
[15:14:22] <paravoid>	 awesome, I'm not crazy :)
[15:14:37] <paravoid>	 jynus' graph above is the first smoking gun we have
[15:14:41] <Krinkle>	 < server: mw1323.eqiad.wmnet
[15:14:41] <Krinkle>	 < x-cache: cp1087 pass, cp3042 pass, cp3030 pass
[15:14:41] <Krinkle>	 < backend-timing: D=237033 t=1565795372190859
[15:14:47] <bblack>	 you could still be crazy, we just lack proof now!
[15:14:48] <jynus>	 my second guess would be higher load
[15:15:04] <jynus>	 note my db focus is biased
[15:15:23] <_joe_>	 paravoid: well we have the data from the profiling sessions too
[15:15:38] <_joe_>	 the difference is in your case the page gets fully re-parsed
[15:15:44] <_joe_>	 so the parsercache gets skipped
[15:15:47] <Krinkle>	 < server: mw1271.eqiad.wmnet
[15:15:47] <Krinkle>	 < backend-timing: D=8474522 t=1565795702982884
[15:15:55] <jynus>	 I would like to see the purge load too
[15:16:29] <bblack>	 broken-record-mode: there was the creation of a new wiki, which was apparently problematic, around the right timeframe, and eventually a related config patch about something to do with ES and/or DB stuff later on
[15:16:41] <jynus>	 oh, that could affect that
[15:16:48] <jynus>	 but wasn't that more hours ago?
[15:17:10] <_joe_>	 bblack: that seems very related yes
[15:17:10] <jynus>	 14:01 reedy@deploy1001: Synchronized wmf-config/interwiki.php: Update interwiki cache + some expiration?
[15:17:15] <Krinkle>	 The only message logged in Logstash for that request (+host:mw1271 AND reqId:"XVQldgpAAEIAAA66LfAAAADR") is : [slow-parse] 8.08s Greece
[15:17:22] <Krinkle>	 From the Poolcounter layer
[15:17:38] <_joe_>	 so you are parsing that page, yes
[15:17:40] <Krinkle>	 no info/warning/error anything besides that
[15:17:41] <Krinkle>	 Yep
[15:17:45] <_joe_>	 jynus: yeah it sounds like a candidate
[15:17:57] <jynus>	 in fact, there was issues with es hosts on addwiki
[15:17:59] <bblack>	 the very first logs about creating the wiki was ~12:24, and there was some dblists update from it around 13:50
[15:18:03] <bblack>	 13:53 <+logmsgbot> !log reedy@deploy1001 Synchronized dblists/: T212881 (duration: 00m 48s)
[15:18:04] <stashbot>	 T212881: addWiki.php broken creating ES tables - https://phabricator.wikimedia.org/T212881
[15:18:06] <bblack>	 13:53 <+stashbot> Logged the message at https://wikitech.wikimedia.org/wiki/Server_Admin_Log
[15:18:08] <jynus>	 which relates to my previous graph
[15:18:09] <bblack>	 13:53 <+stashbot> T212881: addWiki.php broken creating ES tables - https://phabricator.wikimedia.org/T212881
[15:18:30] <jynus>	 https://phabricator.wikimedia.org/T212881
[15:18:36] <jynus>	 that one :-)
[15:19:29] <_joe_>	 how can creating a new wiki create issues on the other wikis, but only for some users?
[15:19:47] <_joe_>	 I'm willing to bet it happens to some users up to a certain ID or something equally horrific
[15:19:57] <_joe_>	 because some db update failed midway through
[15:20:00] <jynus>	 well, hipothetical
[15:20:18] <jynus>	 it could be stuck in a loop trying to store content for the new wiki
[15:20:21] <_joe_>	 yes, I'm trying to evolve that hypothesis
[15:20:22] <jynus>	 and parsing
[15:20:33] <jynus>	 or some other problem affecting other wikis
[15:20:37] <_joe_>	 but we have no errors
[15:20:38] <godog>	 varnish purges went up at ~12, the rate itself though doesn't seem unusual though if you look back e.g. a week: https://grafana.wikimedia.org/d/000000180/varnish-http-requests?panelId=7&fullscreen&orgId=1&from=now-12h&to=now
[15:21:01] <jynus>	 do you know the name of the purge job on queue?
[15:21:07] <jynus>	 just to discard that too
[15:21:42] <godog>	 I don't know offhand no, I hope it has purge in the name tho
[15:21:48] <_joe_>	 that would affect everyone
[15:21:56] <_joe_>	 not just paravoid and a handful other users
[15:22:03] <jynus>	 I know
[15:22:12] <_joe_>	 well not knowing how much "a handful" is
[15:22:12] <jynus>	 nothing strange on the job queue that I can see
[15:22:23] <_joe_>	 jynus: can you try with your historical wiki user?
[15:22:25] <_joe_>	 the private one
[15:22:37] <_joe_>	 not the wmf one
[15:22:38] <jynus>	 sorry, didn't get that
[15:22:46] <jynus>	 a, mw personal user?
[15:22:50] <_joe_>	 you have a wiki user from before joining the wmf
[15:22:51] <_joe_>	 yes
[15:22:58] <jynus>	 checking
[15:22:59] <_joe_>	 that's bound to be an older account
[15:23:02] <jynus>	 Greece ?
[15:23:07] <_joe_>	 yep, for instance
[15:23:22] <godog>	 also are the problems for enwiki only or other wikis too ?
[15:23:28] <_joe_>	 godog: others too
[15:23:36] <paravoid>	 users in #-tech reported a serbian wiki
[15:23:37] <_joe_>	 godog: the original report was for srwiki IIRC
[15:23:39] <jynus>	 instant load
[15:23:44] <paravoid>	 (not sure if it was wp)
[15:23:45] <godog>	 trying to reproduce as well with my user on multiple wikis, so far no luck
[15:23:48] <godog>	 thanks
[15:23:51] <_joe_>	 jynus: ok
[15:24:05] <_joe_>	 paravoid: you see the same slowness on every page?
[15:24:09] <jynus>	 hitting random now
[15:24:09] <paravoid>	 no
[15:24:16] <Krinkle>	 jobrunner errors from mediawiki: https://logstash.wikimedia.org/goto/b35ca9258e09e717fa6c97f89c524314
[15:24:20] <Krinkle>	 (nothing stands out)
[15:24:24] <_joe_>	 if not, can you post the profiling data for a page where you don't see slowness
[15:24:39] <paravoid>	 I don't see it in any other page I've checked
[15:24:49] <_joe_>	 obama loads fine?
[15:24:58] <cdanis>	 yeah I have a 10+yr old volunteer account, have never repro'd there
[15:24:59] <_joe_>	 wth is going on :P
[15:25:10] <paravoid>	 can reproduce it with Obama
[15:25:16] <_joe_>	 ok
[15:25:19] <jynus>	 the number of rows read from parsercache is lowering
[15:25:22] <_joe_>	 so I suspect it happens on every page
[15:25:26] <_joe_>	 but other pages are light
[15:25:29] <_joe_>	 so you don't notice
[15:25:29] <paravoid>	 yeah, possibly
[15:25:41] <jynus>	 which means we are probably losing cache entries slowly?
[15:25:42] <_joe_>	 can you post the profiling for a page you don't see the problem on?
[15:25:53] <_joe_>	 jynus: more users with the problem
[15:26:05] <_joe_>	 ok, this is now a serious incident I think.
[15:26:11] <cdanis>	 actually never mind, I just repro'd backend-timing: D=8834809 t=1565796340524996
[15:26:13] <_joe_>	 if it's spreading
[15:26:19] <cdanis>	 on Greece
[15:26:26] <paravoid>	 _joe_: https://performance.wikimedia.org/xhgui/?url=XVQoDQpAIHsAAGeRUu4AAACX
[15:26:33] <_joe_>	 cdanis: can you repro consistently?
[15:26:51] <cdanis>	 no
[15:27:15] <paravoid>	 given the number of people-hours involved in debugging this, I'd say it's already a pretty serious incident :)
[15:27:49] <cdanis>	 only intermittently, _joe_
[15:27:50] <Krinkle>	 Backend Save timing - does not appear to be affected ; https://grafana.wikimedia.org/d/000000429/backend-save-timing-breakdown?refresh=5m&orgId=1&from=now-2d&to=now
[15:28:13] <cdanis>	 backend-timing: D=6015811 t=1565796420801192 on my first load of https://en.wikipedia.org/wiki/Massachusetts?xx=yy but not when reloading or changing the garbage query parameter
[15:28:44] <_joe_>	 oh so without cookies?
[15:28:55] <cdanis>	 no, logged in as an old volunteer account
[15:28:58] <_joe_>	 ok
[15:29:03] <paravoid>	 shdubsh and I have a 1:1 coming up, do you need me?
[15:29:04] <cdanis>	 backend-timing: D=2967710 t=1565796513387756 on another page
[15:29:07] <_joe_>	 you shouldn't need to do cache-busting then
[15:29:11] <cdanis>	 ah true
[15:29:20] <_joe_>	 in that case you are forcing a reparse
[15:29:26] * Krinkle editing PHP files on mwdebug1001
[15:29:28] <_joe_>	 no, scratch that
[15:30:47] <paravoid>	 chanserv changed the topic? lol
[15:31:01] <cdanis>	 paravoid: yes, +t in here and no one can get ops
[15:31:16] <cdanis>	 but I have special disposition to change the topic via chanserv, we really need to fix the perms here
[15:34:00] <cdanis>	 would adding a new wiki change parsercache keys in any way?
[15:34:11] <cdanis>	 it still does not make sense that it is for a subset of users, ofc
[15:34:30] <jynus>	 cdanis: it would only change it in the trivial way: by adding cached content for the new one
[15:39:51] <jynus>	 so new guess: the deployment of the wiki had some collateral config change which doesn't break the parsing, but makes it less efficient
[15:39:58] <Krinkle>	 [DEBUG] CdnCacheUpdate::HTCPPurgePurging URL https://en.m.wikipedia.org/wiki/Greece via HTCP
[15:40:04] <Krinkle>	 Each time I request it via mwdebug, this also happens
[15:40:04] <jynus>	 I will check the diffs
[15:40:05] <Krinkle>	 which is odd
[15:40:17] <Krinkle>	 But in line with what we're thinking
[15:40:36] <Krinkle>	 (X-Wikimedia-Debug: … ; log)
[15:40:54] <jynus>	 uff https://phabricator.wikimedia.org/T212881#5413761
[15:41:05] <cdanis>	 I have never managed to reproduce it on my WMF account, but can get it to happen intermittently on my ancient volunteer account
[15:41:09] <jynus>	 "The ids look weird. It is using the wrong first two ids... possibly something to do with aawiki? Why does it choose 256 and 257 for the first text rows for aawiki?"
[15:41:11] <cdanis>	 I have no idea if that is even a data point
[15:41:51] <Krinkle>	 I've dumped the cacheKey used from PoolWorkArticleView.php, which is "PoolWorkArticleView::__construct cache key: enwiki:pcache:idhash:12108-0!canonical!tmh-videojs" for me on Greece.
[15:42:01] <Krinkle>	 and it's the same on repeat views.
[15:42:08] <Krinkle>	 So it's not churning the key for example
[15:42:17] <jynus>	 ok, my theory invalidated
[15:42:29] <jynus>	 so run out of ideas
[15:42:35] <cdanis>	 Krinkle: do you happen to know what was in the updates to T212881 that Reedy deleted?  or what Reedy is up to now? :)
[15:42:43] <stashbot>	 T212881: addWiki.php broken creating ES tables - https://phabricator.wikimedia.org/T212881
[15:42:47] <Reedy>	 cdanis: I just !log-d on the wrong task
[15:42:53] <Reedy>	 it was some sync-files for the wiki creation
[15:42:54] <cdanis>	 ah ok
[15:44:39] <Krinkle>	 Reedy is now next to me
[15:48:43] <cdanis>	 I managed to reproduce once while logged out, but only once; it happens much more often when logged into my volunteer account
[15:49:24] <Krinkle>	 One hunch is that maybe poolcounter is misbehaving
[15:49:28] <Krinkle>	 but we don't have a dash for it
[15:49:40] <Krinkle>	 I'll be back in a bit, hackathon running out of food
[15:53:53] <_joe_>	 I don't think poolcounter can misbehave for paravoid and not for me
[16:01:51] <paravoid>	 infra foundations is having our weekly meeting now
[16:02:00] <paravoid>	 let me know if some or all of us are needed
[16:03:13] <Krinkle>	 _joe_: right.
[16:03:22] <bblack>	 I'm assuming for now most of the debugging is happening in-person with Krinkle & Reedy
[16:03:49] <Krinkle>	 It is not. We are having pizza AFK as of 10min
[16:03:54] <bblack>	 ok :)
[16:04:22] <cdanis>	 I can pretty consistently repro on my volunteer acct, lmk if that is helpful
[16:04:51] <_joe_>	 and not on our work acct?
[16:05:13] <_joe_>	 btw
[16:05:16] <cdanis>	 yes, have never repro'd from my WMF acct
[16:05:22] <_joe_>	 the timing spike we saw has recovered
[16:05:28] <_joe_>	 this problem had nothing to do with it
[16:05:38] <_joe_>	 so time correlation isn't so sure anymore with anything
[16:05:47] <_joe_>	 we noticed now, can be ongoing since days
[16:05:56] <bblack>	 you mean the earlier graphs taking off ~12:54 thing?
[16:05:57] <_joe_>	 or well this morning or yesterday evening for what we know
[16:06:00] <_joe_>	 yes
[16:06:03] <bblack>	 ok
[16:06:11] <_joe_>	 https://grafana.wikimedia.org/d/RIA1lzDZk/application-servers-red-dashboard?panelId=9&fullscreen&orgId=1&from=now-12h&to=now&var-datasource=eqiad%20prometheus%2Fops&var-cluster=appserver&var-method=GET&var-code=200
[16:14:19] <jijiki>	 I have not been much involved with the incident but ping me if an extra sre is needed
[16:14:39] <jijiki>	 I will be around either way
[16:19:34] <_joe_>	 Krinkle: I think we really need your help figuring out what's going on
[16:19:48] <_joe_>	 or anyone else who knows mw internals well enough
[16:20:52] <_joe_>	 what I have is: at some point today, after 15:30 I guess, for some logged in users we're reparsing (all?) pages consistently
[16:21:51] <_joe_>	 this https://grafana.wikimedia.org/d/000000278/mysql-aggregated?orgId=1&from=1565786732399&to=1565801943823&var-dc=eqiad%20prometheus%2Fops&var-group=core&var-shard=es1&var-shard=es3&var-role=All&panelId=8&fullscreen hints the proble started at 15:00
[16:22:28] <_joe_>	 the positive part is this is not degrading, afaict
[16:23:42] <_joe_>	 I would also add this latter graph can be a red herring, we have such steep rises in es read all the time
[16:24:20] <_joe_>	 and we don't have users consistently taking forever to get a page because they're not hitting the parsercache ever
[16:25:37] <bblack>	 paravoi.d's first report was ~13:26 here, and -tech reports go back to 10:37
[16:25:50] <bblack>	 I think
[16:27:37] <Krinkle>	 Hi again. I'll get a desk somewhere 5min
[16:28:18] <_joe_>	 bblack: ugh you're right
[16:28:21] <Krinkle>	 Campus is closing down after 15min.. shit
[16:28:32] <_joe_>	 I was somehow reading that completely wrong :/
[16:29:42] <_joe_>	 ok I guess I have to call up other people too
[16:29:56] <bblack>	 also the -tech report was srwiki which is s5, and the other was enwiki on s1
[16:30:01] <bblack>	 so not shard-specific
[16:30:02] <Krinkle>	 I'll have to get to the hotel first. There in 18-20 min. I'll keep thinking and be on irc meanwhile
[16:30:53] <Krinkle>	 One think I'd like to know is whether time spent is mostly in parsing or also outside that halted somewhere
[16:31:10] <_joe_>	 Krinkle: it seems all in parsing
[16:31:14] <Krinkle>	 Eg compare backend timing to the slow-parse log entry
[16:31:33] <_joe_>	 but why is paravoid constantly parsing that page and I'm not?
[16:31:41] <_joe_>	 it's user-specific
[16:31:50] <_joe_>	 and that's unexplicable to me
[16:32:03] <_joe_>	 my user => use parsercache, fast response
[16:32:04] <duesen>	 hey
[16:32:23] <_joe_>	 paravoid's user => reparses every page, slow response on large pages
[16:32:25] <duesen>	 _joe_: note that i may be a mediawiki expert, but i'm no expert on debugging the live system
[16:32:29] <duesen>	 you want Krinkle for that
[16:32:39] <_joe_>	 duesen: in a gist, this is our problem
[16:32:43] <Krinkle>	 If we know that means there must be some cookie, geo or user-Id dependent logic in the decision to consider parser cache hit valid or the poolcounter interaction
[16:33:20] <_joe_>	 Krinkle: cdanis confirmed his volunteer account is affected, his wmf account is not
[16:33:26] <_joe_>	 so I don't think it's geoip
[16:33:29] <cdanis>	 yeah
[16:33:36] <_joe_>	 it's tied to the user
[16:33:37] <cdanis>	 same machine, just different Chrome profiles
[16:34:24] <_joe_>	 how can user-related data affect the decision to consider the parsercache valid or not?
[16:35:22] <_joe_>	 duesen: if you can answer this question ^^, that is basically what we need for now :P
[16:35:35] <cdanis>	 second question, is there any per-user data that can influence the parsercache key?
[16:35:38] <duesen>	 parser cache entries vary on user options
[16:35:56] <_joe_>	  ok, which ones specifically?
[16:35:59] <duesen>	 there is a "canonical" entry for every page, but there may be entries for e.g. output with a different humbnail size (yes, really)
[16:36:18] <duesen>	 The list is buried in ParserOptions, let me check
[16:36:20] <_joe_>	 ok so let me try to alter my settings
[16:36:22] <duesen>	 anomie is the expert on this
[16:36:55] <duesen>	 private static $inCacheKey = [
[16:36:55] <duesen>	 		'dateformat' => true,
[16:36:55] <duesen>	 		'numberheadings' => true,
[16:36:55] <duesen>	 		'thumbsize' => true,
[16:36:55] <duesen>	 		'stubthreshold' => true,
[16:36:56] <duesen>	 		'printable' => true,
[16:36:58] <duesen>	 		'userlang' => true,
[16:37:00] <duesen>	 	];
[16:37:08] <_joe_>	 userlang I expected
[16:37:17] <_joe_>	 that's why I immediately asked paravoid about it
[16:37:27] <duesen>	 but only effective if the page actually makes use of it, e.g. with {{int:xyz}}
[16:37:40] <duesen>	 dateformat?
[16:38:05] <duesen>	 probably only effective if used, i.e. the page contains {{DATEFORMAT:...}}
[16:38:10] <duesen>	 thumbsize is the nasty one
[16:38:39] <bblack>	 also another little peice of evidence, was all the script timeout errors in pvoid's browser view (although I don't remember if that was only on mwdebug)
[16:38:45] <bblack>	 https://tty.gr/s/enwiki-greece-timeout.png
[16:38:55] <cdanis>	 bblack: I think that was just mwdebug
[16:39:01] <bblack>	 oh ok
[16:39:05] <_joe_>	 bblack: that's because mwdebug dies under heavy parsing, yes
[16:39:18] <cdanis>	 what is the default thumbsize?
[16:39:35] <duesen>	 we should just kill thumbsize and numberheadings settings
[16:39:41] <cdanis>	 I have 200px on my volunteer acct and 220px on my WMF account
[16:39:53] <cdanis>	 I don't recall ever adjusting the size on either but my volunteer acct is so old I don't really know
[16:39:55] <bblack>	 did you choose those, or just defaults changed over time for new accounts?
[16:39:55] <_joe_>	 cdanis: ok so you can do this
[16:40:07] <_joe_>	 go to view-source:https://en.wikipedia.org/wiki/Greece
[16:40:16] <_joe_>	 and search for NewPP limit report
[16:40:35] <_joe_>	 I have Cached time: 20190814160703
[16:40:55] <cdanis>	 https://phabricator.wikimedia.org/P8909
[16:40:57] <duesen>	 $wgThumbLimits is the relevant setting
[16:40:58] <_joe_>	 if you use an account that has a modified thumb size
[16:41:03] <duesen>	 though i don't know which of them is the default
[16:41:05] <_joe_>	 you should see a different time
[16:41:13] <_joe_>	 but on reload, you should see the same time
[16:41:20] <cdanis>	 _joe_: I got a reparse *after* changing my thumbsize to 220px
[16:41:32] <_joe_>	 cdanis: uhm
[16:41:39] <_joe_>	 but I see the cached time is the same as mine
[16:41:59] <duesen>	 220px seems to be the default
[16:42:04] <_joe_>	 so that's not a reparse
[16:42:08] <_joe_>	 the one you pasted
[16:42:08] <cdanis>	 oh you are right
[16:42:12] <duesen>	 funny, that's not even in the vanilla list in mw core
[16:42:26] <_joe_>	 so lemme try to debug this myself
[16:43:01] <_joe_>	 ok
[16:43:08] <duesen>	 *snort*
[16:43:11] <duesen>	 'wgThumbLimits' => [
[16:43:11] <duesen>	 	'default' => [ 120, 150, 180, 200, 220, 250, 300, 400 ],
[16:43:11] <duesen>	 	'+itwikiquote' => [ 360 ],
[16:43:11] <duesen>	 	'svwiki' => [ 120, 200, 250, 300, 360 ],
[16:43:11] <duesen>	 ],
[16:43:12] <_joe_>	 now with thumb size changed
[16:43:19] <_joe_>	 I see a reparse
[16:43:48] <_joe_>	 and on a reload, I see the same parsercache version
[16:44:01] <_joe_>	 so thumb size uses a different parsercache
[16:44:03] <cdanis>	 so why was paravoid seeing consistent reparses then?
[16:44:11] <cdanis>	 _joe_: yeah, you can see the key change
[16:44:12] <_joe_>	 yeah not thumbsize
[16:44:30] <_joe_>	 cdanis: so with your old user you keep seeing reparses?
[16:44:57] <cdanis>	 no
[16:45:46] <cdanis>	 if I go to arbitrary pages I can often get a reparse
[16:46:06] <cdanis>	 but reloading them once I have loaded a given page once does not seem to trigger a reparse
[16:46:10] <_joe_>	 which is expected given your thumb size
[16:46:22] <_joe_>	 ok so it's not so strange.
[16:46:25] <cdanis>	 yes, although I don't remember it being slow like this in the past
[16:46:32] <cdanis>	 paravoid: what thumbsize do you have?
[16:46:57] <_joe_>	 what is the db table where I find user preferences?
[16:47:13] <duesen>	 in the HTML output, there should be a line like this:
[16:47:13] <duesen>	 Saved in parser cache with key mediawikiwiki:pcache:idhash:99540-0!canonical and timestamp 20190813143837 and revision id 3067163
[16:47:20] <duesen>	 this will tell us the parser cache key
[16:47:28] <bblack>	 FWIW, in my logged-in WMF account from chromium, I get:
[16:47:28] <_joe_>	 ok
[16:47:30] <duesen>	 which will tell us which options made it vary
[16:47:32] <bblack>	 Parsed by mw1320
[16:47:32] <bblack>	 Cached time: 20190814160703
[16:47:41] <bblack>	 and the cached time seems to remain stable, I assume that means no reparse
[16:47:42] <cdanis>	 yeah in my case duesen it is the thumbsize key that's different from canonical
[16:47:42] <duesen>	 it'S in an HTML comment
[16:47:46] <_joe_>	 paravoid: we need you to check the html you get for the Greece page :)
[16:47:50] <cdanis>	 bblack: do you have a canonical key?
[16:47:51] <bblack>	 but the page load time is ~1000ms
[16:47:56] <cdanis>	 <!-- Saved in parser cache with key enwiki:pcache:idhash:21216-0!thumbsize=3 and timestamp 20190814164334 and revision id 910396398
[16:47:59] <cdanis>	 vs
[16:48:03] <cdanis>	 !canonical
[16:48:06] <duesen>	 indeed
[16:48:12] <paravoid>	 hey
[16:48:15] <bblack>	 <!-- Saved in parser cache with key enwiki:pcache:idhash:12108-0!canonical and timestamp 20190814160655 and revision id 910317158
[16:48:18] <bblack>	 ^is what I get
[16:48:59] <bblack>	 I switched my prefs to 200px thumb size, didn't seem to change load time significantly, then changed it back to 220px.
[16:49:15] <duesen>	 anything that doesn't have !caninical is likely to hit a reparse (and be slow)
[16:49:24] <paravoid>	 sorry was in a meeting, and I have another one coming up in 10
[16:49:26] <paravoid>	 what do you need?
[16:49:28] <_joe_>	 bblack: bcause I parsed that page at 200px for you
[16:49:33] <bblack>	 ah
[16:49:39] <_joe_>	 paravoid: open the greece page again, then look at the html
[16:49:54] <cdanis>	 then Ctrl-F for: saved in parser cache
[16:49:54] <paravoid>	 parsercache comment?
[16:49:57] <cdanis>	 and paste that line
[16:50:00] <_joe_>	 yes
[16:50:04] <paravoid>	 pp what was it
[16:50:10] <_joe_>	 NewPP
[16:50:12] <_joe_>	 :P
[16:50:14] <_joe_>	 it's new!
[16:50:30] <paravoid>	 Parsed by mw1263
[16:50:30] <paravoid>	 Cached time: 20190814164950
[16:50:30] <paravoid>	 Cache expiry: 2592000
[16:50:30] <paravoid>	 Dynamic content: false
[16:50:30] <paravoid>	 Complications: [vary‐revision‐sha1]
[16:50:39] <duesen>	 paravoid: just the one line at the bottom
[16:50:43] <paravoid>	 <!-- Saved in parser cache with key enwiki:pcache:idhash:12108-0!canonical!tmh-videojs and timestamp 20190814164942 and revision id 910317158
[16:50:45] <duesen>	 the one with the parser cache key
[16:50:53] <duesen>	 ooohhh.
[16:51:00] <duesen>	 !tmh-videojs
[16:51:03] <duesen>	 that'S the culprit
[16:51:11] <duesen>	 no idea what it is, but it'S the cause ;)
[16:51:12] <paravoid>	 I have all beta features by default
[16:51:13] <_joe_>	 paravoid: can you reload?
[16:51:18] <paravoid>	 and I see one now that says "new video player"
[16:51:28] <_joe_>	 and see if you see the same comment?
[16:51:32] <Krinkle>	 Try resetting user preferences on both accounts
[16:51:44] <Krinkle>	 Yeah user id or pref related
[16:51:55] <duesen>	 hmmm....
[16:52:04] <paravoid>	 reload is
[16:52:04] <paravoid>	 <!-- Saved in parser cache with key enwiki:pcache:idhash:12108-0!canonical!tmh-videojs and timestamp 20190814165135 and revision id 910317158
[16:52:08] <duesen>	 so, !tmh-videojs gets slapped on even if there is no video on the page?
[16:52:13] <duesen>	 I'd consider that a bug
[16:52:35] <paravoid>	 isn't the bug that it gets reparsed every time instead of getting cached?
[16:52:37] <_joe_>	 ok I enabled the flag too
[16:52:45] <Krinkle>	 Why would that cause a consistent cache miss?
[16:52:49] <_joe_>	 <!-- Saved in parser cache with key enwiki:pcache:idhash:12108-0!thumbsize=3!tmh-videojs and timestamp 20190814165227 and revision id 910317158
[16:52:52] <paravoid>	 even with tmh-videojs, you'd expect a lower hit ratio but subseqeunt reloads to be a hit, no?
[16:52:57] <_joe_>	 reloading now
[16:53:04] <Krinkle>	 Should still be saveable and gettable
[16:53:05] <_joe_>	 and yes
[16:53:09] <duesen>	 yes, it shouldn't re-parse on re-load
[16:53:13] <_joe_>	 consistent cache ,misses
[16:53:13] <duesen>	 unless it messes with the ttl
[16:53:15] <bblack>	 I just went into my appearance prefs and changed a bunch of them to new values (based on the stuff listed above, things that looked likely), and now I have a consistent 9s load time :P
[16:53:20] <duesen>	 that would be *really* bad
[16:53:22] <_joe_>	 <!-- Saved in parser cache with key enwiki:pcache:idhash:12108-0!thumbsize=3!tmh-videojs and timestamp 20190814165253 and revision id 910317158
[16:53:22] <Krinkle>	 (I agreee it's likely a bug but possible unrelated )
[16:53:24] <bblack>	 will see if I can pare that down
[16:53:24] <_joe_>	 ok
[16:53:31] <cdanis>	 bblack: I think that's expected
[16:53:31] <_joe_>	 we need to disable that beta feature :P
[16:53:31] <paravoid>	 awesomeness
[16:53:37] <_joe_>	 ahahahah
[16:53:42] <bblack>	 cdanis: should be expected only once, then parsercached, right?
[16:53:46] <_joe_>	 who wants to do the honours?
[16:53:47] <bblack>	 I'm getting it repeatedly now
[16:53:47] <duesen>	 Cache expiry: 2592000 <-- that looks ok
[16:53:58] <cdanis>	 bblack: that's interesting, if it is consistent for the same page
[16:54:04] <_joe_>	 duesen: you see with that key I always get a parser cache miss
[16:54:15] <paravoid>	 TIL that most SREs are conservative enough to not have "enable all beta features automatically" enabled :P
[16:54:20] <_joe_>	 bblack: what are you getting?
[16:54:30] <_joe_>	 paravoid: ahahahah
[16:54:40] <_joe_>	 I did have them in the past
[16:54:46] <bblack>	 yes, consistent for Greece, I get 9s now, after changing a bunch of Appearance settings that were noted earlier in parsercache key variance.  I'm going to change some back and see if I can narrow to one setting.
[16:54:59] * duesen has to be in a meeting in 5
[16:55:02] <_joe_>	 bblack: tmh_videojs
[16:55:05] <_joe_>	 is what I have
[16:55:06] <paravoid>	 the page does have the national anthem widget
[16:55:07] <_joe_>	 but maybe
[16:55:12] <_joe_>	 I have a horrible suspect
[16:55:21] <paravoid>	 it's not video, but it is an audio player
[16:55:30] <paravoid>	 so that's probably why I've only been getting it on that page
[16:55:40] <duesen>	 what I find strange is that it has both !canonical and !tmh-videojs. If it has an extra option, it'S not canonical?...
[16:55:45] <duesen>	 Something is odd there
[16:56:02] <paravoid>	 (just speculating, no time to actually check)
[16:56:09] <_joe_>	 duesen: I suspect that extension causes the parsercache to be invalid
[16:56:19] <bblack>	 I don't get a "saved in parser cache" line anymore on my 9s loads
[16:56:21] <_joe_>	 so when trying to read it, it's invalid and not read
[16:56:29] <_joe_>	 bblack: uh?
[16:56:44] <_joe_>	 that should be in every page, you get the report even if you don't parse it IIRC
[16:56:45] <duesen>	 _joe_: yea, but how? typically you'd do that by setting the ttl. but the Cache expiry field as reported seems fine
[16:57:13] <_joe_>	 duesen: say when you read from the parser cache, you instantiate some objects I guess?
[16:57:20] <duesen>	 yes
[16:57:22] <bblack>	 _joe_: https://phabricator.wikimedia.org/P8910
[16:57:27] <duesen>	 via php serialization, in fact
[16:57:27] <bblack>	 (that's the whole NewPP block)
[16:57:32] <_joe_>	 or anyways, the code must validate what's in the parsercache
[16:57:36] <duesen>	 oh, right
[16:57:41] <duesen>	 if deserialization fails, that would explain it
[16:57:53] <duesen>	 maybe the player puts something nasty into the ParyserOptions object
[16:57:59] <_joe_>	 bblack: what baffles me is the 9s load time in that case
[16:58:01] <duesen>	 but that kind of failure would spam the logs
[16:58:07] <paravoid>	 loading https://en.wikipedia.org/wiki/GMT instead gives me a enwiki:pcache:idhash:12701-0!canonical!tmh-videojs key *but* with the same timestamp on every load
[16:58:08] <_joe_>	 duesen: uhm ok
[16:58:14] <duesen>	 well... it would show in the logs. not spam, if not many people have the extension enabled
[16:58:31] <paravoid>	 so it is likely this shows up only if there is a player in the page
[16:58:44] <bblack>	 anyways, I'm changing one preference back to my previous settings at a time and reloading now, will see what gets me back to normal
[16:58:46] <duesen>	 i don't know my way around the logs so well. Krinkle would know how to find php deserialization errors, i guess
[16:58:50] <_joe_>	 there is a player in the greece page?
[16:58:52] <Krinkle>	 Almost in lobby need 3min
[16:58:55] <cdanis>	 _joe_: audio
[16:58:57] <paravoid>	 _joe_: audio, national anthem
[16:59:03] <_joe_>	 ok
[16:59:12] <_joe_>	 so yeah, that might make sense!
[16:59:23] <paravoid>	 Italy is slow to load too :P
[16:59:31] <_joe_>	 it's august
[16:59:34] <_joe_>	 give us a break
[16:59:34] <paravoid>	 hahahaha
[16:59:51] <volans>	 italy is closed for holidays
[16:59:55] <duesen>	 if there is no player on the page, the !tmh-videojs think shouldn't be in the cache key. that's a bug. but not the bad one, it seems.
[17:00:04] <_joe_>	 paravoid: and the audio there as well
[17:00:16] <bblack>	 is this meaningful or abnormal in NewPP? : Complications: [vary‐revision‐sha1]
[17:00:41] <_joe_>	 while for example https://en.wikipedia.org/wiki/Migration_Period works fine
[17:00:48] <duesen>	 bblack: i have never seen that before
[17:00:51] <_joe_>	 I think we narrowed it down to that beta feature?
[17:01:02] <duesen>	 yea
[17:01:11] <duesen>	 specifically, loading a page that has the player from the parser cache
[17:01:14] <duesen>	 somethign goes wrong there
[17:01:21] <duesen>	 (or maybe even when writing to the cache?)
[17:01:37] <Krinkle>	 Reading backscroll now.
[17:01:37] <duesen>	 "saved to parser cache" may be a lie
[17:02:08] <_joe_>	 we can check I guess
[17:02:30] <Krinkle>	 Have any measures been taken so far?
[17:02:35] <cdanis>	 no
[17:02:41] <Krinkle>	 OK. good
[17:02:45] <cdanis>	 aside from some users experimenting with changing their rendering settings
[17:03:10] <Krinkle>	 videojs, ack that it's weird. if it's appending that hash to pages without audio/video, that's a bug that should block non-beta roll out of the feature but otherwise should not be an issue.
[17:03:36] <Krinkle>	 videojs vs canonical, ack, that's also weird. videojs means non-canonical. but also, given the cache does not appear to churn due to it, seems like a red-herring to me at glance as well
[17:03:54] <_joe_>	 the user that first reported the problem in #-tech has the beta feature enabled FWIW
[17:04:38] <Krinkle>	 Someone here was able to repro on one account, but not another. Can they reset their user prefs from Special:Preferences on both accounts and then retry with both?
[17:05:04] <bblack>	 maybe what I'm seeing is a different issue or whatever, but what I narrowed down to is this:
[17:05:09] <cdanis>	 Krinkle: that looks like it was just my old user account having a different thumbsize
[17:05:32] <bblack>	 if I change the pref "Threshold for stub link formatting" from the default of "Disabled" to 1000 bytes, it never reports saving in cache and always loads slow.
[17:05:41] <Krinkle>	 cdanis: old account with non-canonical thumb size affected or unaffected by the slow/cache-miss?
[17:05:49] <bblack>	 if I put tha tback to disabled, the other settings don't seem to have much impact
[17:05:52] <cdanis>	 Krinkle: affected
[17:06:10] <Krinkle>	 bblack: That's more or less expected I think. there are a number of variations we don't cache.
[17:06:19] <Krinkle>	 (I think)
[17:07:02] <_joe_>	 Krinkle: I can confirm I get the reparses with the beta feature on, and I don't with it off
[17:07:06] <bblack>	 ok
[17:07:12] <_joe_>	 Krinkle: but only on pages with videos or audios
[17:07:15] <_joe_>	 other pages are fine
[17:07:26] <cdanis>	 so the beta feature isn't actually saving results to parsercache?
[17:08:10] <Krinkle>	 I'm looking into the code now that decides whether ParserOutput in PoolcounterWork is "cacheable" and whether that can be misused by tmh/videojs mode.
[17:08:12] <bblack>	 does pvoid have beta?
[17:08:22] <cdanis>	 bblack: pvoid auto opts in to all betas
[17:08:53] * Krinkle scap pulls to reset mwdebug1001 and then goes to edit its files
[17:09:31] <paravoid>	 I think a meaningful actionable is performance metrics for the cohort of users that have beta enabled (or even per each beta feature)
[17:10:22] <bblack>	 hmm yeah, the beta video player does it for me too heh
[17:10:28] <_joe_>	 I'm not sure there is enough statistics for that, some beta features have few hundreds users
[17:10:43] <bblack>	 "Saved in parser cache with key enwiki:pcache:idhash:12108-0!canonical!tmh-videojs", but slow every time
[17:12:00] <Krinkle>	 For Greece:
[17:12:00] <Krinkle>	 PoolWorkArticleView::__construct cache key: enwiki:pcache:idhash:12108-0!canonical!tmh-videojs
[17:12:04] <Krinkle>	 PoolWorkArticleView::doWork cacheable: true
[17:12:17] <Krinkle>	 So it's not an issue with it being marked as un-saveable
[17:14:37] <Krinkle>	 PoolWorkArticleView::doWork PoolCounter-cacheable: true
[17:14:40] <Krinkle>	 PoolWorkArticleView::doWork PoolCounter-isCurrent: true
[17:14:45] <Krinkle>	 PoolWorkArticleView::doWork ParserOutput-isCacheable: true
[17:14:53] <Krinkle>	 all green, and yet it's not there on repeat view somehow
[17:15:16] <cdanis>	 is there some problem stopping keys of that form from getting written to the database?
[17:15:17] <bblack>	 is that printed cache key the actual key, or just input to some other function that might add more stuff to it?
[17:15:27] <Krinkle>	 From https://github.com/wikimedia/mediawiki/blob/8f2f5b916b9c5fd0e3dde53b1cc716b0ac3c1c3c/includes/poolcounter/PoolWorkArticleView.php#L211
[17:15:27] <bblack>	 (and/or hash it)
[17:16:28] <_joe_>	 we should just query the es databases
[17:16:29] <cdanis>	 Krinkle: is there anything that parserCache->save() succeeds?
[17:16:48] <_joe_>	 but managing to find the key on the db and the corresponding table, good luck :P
[17:17:47] <Krinkle>	 cdanis: not exactly, it's void and ends with memc->set() which would log an error in Logstash if it has issues
[17:17:57] <Krinkle>	 it does multiwrite to Memc and SQL
[17:18:14] <Krinkle>	 I'll add some more ad hoc debugg
[17:18:34] <_joe_>	 Krinkle: what's teh key we set to memcached?
[17:18:40] <_joe_>	 that is easy to retrieve
[17:19:02] <_joe_>	 or
[17:19:18] <_joe_>	 we can try to get the parsercache jkey from shell.php
[17:19:34] <_joe_>	 I'm not sure how
[17:20:56] <_joe_>	 hi thedj welcome!
[17:22:10] <Krinkle>	 DJ and Amir helping me in person
[17:22:20] <_joe_>	 I guessed so
[17:22:22] <Krinkle>	 logging Memc->set operations now
[17:22:50] <Krinkle>	 ParserCache::save Memc set key: enwiki:pcache:idoptions:12108  -  ok: true
[17:22:54] <Krinkle>	 ParserCache::save Memc set key: enwiki:pcache:idhash:12108-0!canonical!tmh-videojs  -  ok: true
[17:23:05] <Krinkle>	 _joe_: :)
[17:23:38] <_joe_>	 we should fetch those keys from memcached and see what's inside
[17:23:56] <_joe_>	 I can get to it in 5 minutes
[17:23:59] <Krinkle>	 ok
[17:24:48] <Amir1>	 thedj had the idea that parser cache might be expired and that's why it started to show up now. Is the TTL of parsercache 22 days?
[17:25:02] <Krinkle>	 [caches] INFO parser: MultiWriteBagOStuff
[17:25:36] <marostegui>	 Amir1:  30
[17:25:50] <_joe_>	 Krinkle: I'd look into why it's not /retreiving/ the cache
[17:25:58] <Krinkle>	 Yeah
[17:26:00] <_joe_>	 not if it saves it or not, at this point
[17:26:00] <Krinkle>	 That's next
[17:26:32] <Krinkle>	 Logstash: `channel:AdHocDebug OR channel:ParserCache OR message:parser OR message:parsercache`
[17:26:48] <Krinkle>	 ParserOutput key valid, but rejected by RejectParserCacheValue hook handler.
[17:26:52] <Krinkle>	 thedj wins the cake
[17:27:17] <Krinkle>	 Article::view using parser cache: yes
[17:27:47] <Krinkle>	 This is a last-minute run-time callback with which non-expired parser cache can be forced to appear expired.
[17:28:05] <_joe_>	 I can retrieve the parser cache key from memcached
[17:28:16] <cdanis>	 Warning! Misuse of this hook can effectively disable the parser cache, with serious consequences for high-traffic installations. Use with extreme care.
[17:28:29] <_joe_>	 uh-oh
[17:28:32] <_joe_>	 :P
[17:28:36] <Krinkle>	 Prod extensions using this MW hook: Wikibase, ops/mediawiki-config, Kartographer, TimedMediaHandler
[17:28:40] <Krinkle>	 https://codesearch.wmflabs.org/deployed/?q=RejectParserCacheValue&i=nope&files=&repos=
[17:29:06] <thedj>	 onRejectParserCacheValue always returns false therefore
[17:29:21] <thedj>	                         (
[17:29:23] <thedj>	                                 self::defaultPlayerMode() === 'mwembed' &&
[17:29:26] <thedj>	                                 !in_array( 'mw.MediaWikiPlayer.loader', $parserOutput->getModules() )
[17:29:29] <thedj>	                         ) || (
[17:29:32] <thedj>	                                 self::defaultPlayerMode() === 'videojs' &&
[17:29:35] <thedj>	                                 !in_array( 'ext.tmh.video-js', $parserOutput->getModules() )
[17:29:38] <thedj>	                         )
[17:29:40] <thedj>	 has to be somwehere in there then
[17:29:56] <Krinkle>	 So the static value is wrong, or the ParserOutput->getModules is wrong
[17:31:59] <Krinkle>	 Looks like the static one is wrong. It is not written with the beta feature in mind.
[17:32:08] <Krinkle>	 It is meant to catch if the site config is changed so that we purge stale cache.
[17:32:08] <_joe_>	 Krinkle: hah
[17:32:20] <Krinkle>	 But it is matching the "site default" against the curent object, not the current user pref.
[17:32:21] <Amir1>	 ext.tmh.video-js is never injected, the other part is always true
[17:32:32] <James_F>	 Oops.
[17:32:37] <Krinkle>	 So if you user pref and current object is differenet from site config, it always refuses to persist it
[17:32:48] <Krinkle>	 Which makes sense if it weren't for the fact that it already varies the cache key on it
[17:32:51] <Krinkle>	 We don't need both
[17:33:13] <Krinkle>	 also Amir notices that even if that bug is fixes, it would likely still be broken because TMH never sets "ext.tmh.video-js" in parserOutput->getModules anymore. Which also changed at some point.
[17:33:14] <_joe_>	 Amir1: oh?
[17:33:21] <Krinkle>	 But still, seems like none of this changed recently.
[17:33:38] <_joe_>	 it's the interaction with the beta feature causing hte problem
[17:33:46] <Krinkle>	 Yeah
[17:33:52] <_joe_>	 Krinkle: mind dumping both values in commnets on mwdebug1001 please?
[17:33:53] <Krinkle>	 so likely just induced by the beta pref more popular
[17:33:58] <Krinkle>	 OK
[17:33:58] <_joe_>	 it's easier to reason with the data :)
[17:34:22] <cdanis>	 I'm stepping out for a bit, I'm yet to eat today
[17:34:37] <_joe_>	 ugh
[17:34:47] <_joe_>	 I'm going afk soon too, it's dinner time here
[17:35:37] <_joe_>	 it only happens on pages with a video or an audio, too. Why is that?
[17:35:50] <_joe_>	 well we can now test :P
[17:37:15] <Krinkle>	 Because the hook is only applied on pages with TMH activated
[17:37:19] <Krinkle>	 that makes sense
[17:37:48] <Krinkle>	 First part of the condition in https://gerrit.wikimedia.org/g/mediawiki/extensions/TimedMediaHandler/+/a9a3b431d5c175778b076b7d6c230aa8280c121f/includes/TimedMediaHandlerHooks.php#525
[17:37:58] <thedj>	 https://github.com/wikimedia/mediawiki-extensions-TimedMediaHandler/commit/1ea88c6dd7d179ccf75c7feef498b6e377945b5d
[17:38:02] <Krinkle>	 TimedMediaHandlerHooks::onRejectParserCacheValue mode: mwembed  -  modules_intersect: []
[17:38:07] <Krinkle>	 Which is with the videojs pref
[17:38:12] <Krinkle>	 so in_array will be false
[17:38:21] <Krinkle>	 		$mode = self::defaultPlayerMode();
[17:38:21] <Krinkle>	 		$modules = implode(', ', array_intersect( $parserOutput->getModules(), ['mw.MediaWikiPlayer.loader','ext.tmh.video-js' ]));
[17:38:21] <Krinkle>	 		wfDebugLog( 'AdHocDebug', __METHOD__ . " mode: $mode  -  modules_intersect: $modules" );
[17:38:54] <_joe_>	 Krinkle: do you have the beta active?
[17:39:21] <_joe_>	 so the mode is mwembed
[17:39:30] <_joe_>	 and the module is not in the array
[17:39:37] <Krinkle>	 defaultPlayerMode does not vary on user pref
[17:39:40] <_joe_>	 so we wipe the cdn and return false
[17:39:41] <Krinkle>	 it's the site default
[17:39:45] <Krinkle>	 it's mwembed in prod
[17:39:46] <_joe_>	 ok
[17:39:48] <Krinkle>	 my user pref is videojs
[17:39:53] <James_F>	 The TMH module it now adds in videojs is ext.tmh.player
[17:40:00] <_joe_>	 so what changes is that it loads another module
[17:40:04] <Krinkle>	 Yeah, the module was renamed, which further broke it.
[17:40:05] <_joe_>	 ahha ok
[17:40:11] <Krinkle>	 That's probably the last part of the puzzle that made it more visible.
[17:40:11] <James_F>	 Not ext.tmh.video-js.
[17:40:11] <_joe_>	 lol
[17:40:21] <Krinkle>	 before that at least it somewhat worked.
[17:40:31] <Krinkle>	 although it was already flawed
[17:40:49] <_joe_>	 not sure I follow
[17:40:50] <James_F>	 ext.tmh.player depends on ext.tmh.video-js but RL hasn't walked the tree at this point, has it?
[17:41:05] <Krinkle>	 There is no tree here, it's a flat list of enqueued modules
[17:41:06] <_joe_>	 if defaultplayermode is 'mwembed'
[17:41:11] <Krinkle>	 only addModules plays a role here
[17:41:14] <_joe_>	 only the first condition can ever be true
[17:41:21] <Krinkle>	 Yeah
[17:41:29] <Krinkle>	 which is why anons and most users are fine
[17:41:34] <James_F>	 Right.
[17:41:46] <_joe_>	 so it is just loading a different player than the default would always be broken
[17:41:54] <_joe_>	 ok I get it now
[17:42:11] <Krinkle>	 so most immediate is: This code is broken and must be fixed as otherwise anon views with videojs default will be uncacheable .
[17:42:14] <_joe_>	 I don't think the second part of the brokenness (the wrong name) has any weight there
[17:42:27] <_joe_>	 yeah
[17:42:35] <Krinkle>	 less immedaite is: This code is broken for anyone using videojs beta pref, and will still be fixed even if we update the module name, because defaultPlayer does not consider user preferences.
[17:42:38] <_joe_>	 and maybe the beta be disabled in the meantime?
[17:42:43] <James_F>	 We aren't switching TMH mode to videojs any time soon.
[17:42:43] <Krinkle>	 will still be broken*
[17:42:47] <_joe_>	 oh ok I see
[17:42:58] <_joe_>	 so it's broken for all sites that have videojs as default
[17:43:09] <_joe_>	 Krinkle: cna you cjheck the value for srwiki?
[17:43:11] <James_F>	 It won't break anything for anons until we have videojs as default, which is none, right?
[17:43:15] <Krinkle>	 even more less immediate: This whole hook seems obsolete because we already fragment parser cache key by tmh:videojs so this logic shuldn't be needed.
[17:43:24] <James_F>	 _joe_: This is my feature. It's not rolling out AFAIAA.
[17:43:29] <Krinkle>	 James_F: yeah, except test2wiki I think
[17:43:33] <thedj>	 only test2.wp.org has videojs by default
[17:43:34] <_joe_>	 James_F: oh ok
[17:43:39] <_joe_>	 ok so
[17:43:42] <Krinkle>	 which is non-zero, but should be minimal impact
[17:43:49] <_joe_>	 the most immediate thing is imho disable the beta
[17:43:57] <James_F>	 Krinkle: Oh, yes, test2wiki is the only one.
[17:44:00] <_joe_>	 then understand how to fix the whole logic
[17:44:02] <James_F>	 _joe_: I'll do that.
[17:44:14] <Krinkle>	 I'm gonna sign off from this now given we have no reason to believe it is spreading, and if it does spread rapidly, then emergency handle is to disable the beta pref and/or hack a way to disallow more users from enabling it.
[17:44:27] <_joe_>	 that way we'll stop harming kind souls trying the beta :)
[17:44:32] <James_F>	 Oh, wait. Do we need to disable the beta?
[17:44:35] <_joe_>	 but yeah, that hook needs rethinking
[17:44:37] <James_F>	 Krinkle implies not?
[17:44:43] <_joe_>	 well
[17:44:51] <James_F>	 Because disabling the beta is moderately disruptive.
[17:45:03] <_joe_>	 ok, then a fix is needed :)
[17:45:11] <James_F>	 I can just drop that hook?
[17:45:24] <_joe_>	 we have several thousand users having this issue
[17:45:27] <Krinkle>	 Yeah, keeping the beta  is fine imho as it's been this way for months, and unless it causes infra issues I think we do n't need to do anything "right now"
[17:45:35] <James_F>	 Right.
[17:45:43] <_joe_>	 is the beta ongoing since months?
[17:45:44] <Krinkle>	 OK. Gonna go bak to hackathonian things now
[17:45:59] <thedj>	 _joe_: yup
[17:46:05] <thedj>	 2,5 months at least
[17:46:06] <Krinkle>	 Bleep me on wmf hangouts if you need anything else. see above for standing advice re emergency
[17:46:12] <_joe_>	 strange this was noticed today for the first time
[17:46:25] <thedj>	 i think just slowly more and more users
[17:46:30] <_joe_>	 James_F: I think what Krinkle said makes sense
[17:46:36] <James_F>	 Maybe someone with the pref enabled hit a lot of expensive pages?
[17:46:58] <James_F>	 I'll write a stand-by patch to disable the beta feature just in case.
[17:47:13] <_joe_>	 I got to step afk now. been around since 7 am with not many pauses
[17:48:49] <cdanis>	 thanks James_F
[17:51:06] <James_F>	 Now hunting for the task to reference.
[17:51:22] <James_F>	 Is there one?
[17:51:30] <cdanis>	 there is not
[17:51:38] <cdanis>	 there are some very sketchy notes I've been collecting in the doc in the topic
[17:51:39] <James_F>	 OK, will just put "see SRE".
[17:51:43] <James_F>	 Aha, thanks.
[17:52:11] <paravoid>	 I very much doubt this has been like that for 2.5 months
[17:52:17] <paravoid>	 I'm confident that I'd have noticed
[17:52:32] <paravoid>	 and also it's one hell of a coincidence that multiple users + me all noticed today :)
[17:53:41] <thedj>	 right. so likely you only notice this on longer pages, because on short pages, the parsing doesn't take so long that you actually notice
[17:53:50] <thedj>	 which is why we didn't really notice before.
[17:53:56] <Krinkle>	 Very few pages still have multi-digit parse times.
[17:54:26] <Krinkle>	 And thedj says he didn't notice the issue but that turns out because he already has other preferences that disable parser cache for him, so enabling the beta pref didn't make it any slower for him
[17:57:59] <thedj>	 i;'ll write the ticket
[17:59:26] <James_F>	 https://gerrit.wikimedia.org/r/#/c/operations/mediawiki-config/+/530187 is the emergency disable patch if it's needed.
[17:59:39] <James_F>	 It'll be messy, but it'd stop people adding the beta feature.
[18:00:35] <James_F>	 (And as they touch their preferences, existing people would get emptied out.)
[18:05:10] <thedj>	 https://phabricator.wikimedia.org/T230505
[18:11:24] <thedj>	 _joe_: amend as you see fit ;)
[19:28:12] <cdanis>	 thanks thedj, added that to the doc