| • demon | |
| Feb 11 2015, 4:24 PM |
| F42789: devices.tsv | |
| Feb 17 2015, 11:32 PM |
| F42788: countries.tsv | |
| Feb 17 2015, 11:32 PM |
Spotted in production:
478 Undefined property: SpecialBannerRandom::$allocContext in /srv/mediawiki/php-1.25wmf16/extensions/CentralNotice/special/SpecialBannerRandom.php on line 27 478 error: Argument 1 passed to BannerChooser::__construct() must be an instance of AllocationContext, null given in /srv/mediawiki/php-1.25wmf16/extensions/CentralNotice/includes/BannerChooser.php on line 41
This is the single noisiest item in the hhvm log right now. Please fix as it drowns out all other information.
In both varnish-ncsa and varnish-kafka based logs, we only see ~30K/day requests to Special:BannerRandom.
Reading the text cluster's varnish setup, it looks like there should be 1 retry per 503. Hence each of the above ~30K/day requests should account for 4 lines in hhvm.log (2xNotice, 2xFatal).
For all the 20-ish varnish-kafka based log lines that I checked, I could find those expected 4 lines in hhvm.log.
However, hhvm.log also has SpecialBannerRandom Notices/BannerChooser Failures that seem to lack a corresponding varnish-kafka log line.
For example on ~2015-02-12T07:13:06 only one Special:BannerRandom request is in the the varnish-kafka logs (with a few seconds buffer before/after without such a request). But the hhvm.log has 32 corresponding lines. That's much more than the 4 expected lines.
We store the varnish-kafka logs unsampled, so it cannot be sampling.
And the varnish-kafka logs seem flawless for the above timestamp.
(Lacking access to the app-servers, I cannot respond to those two questions)
Thanks a ton, @QChris!! A few more notes:
Thanks much!! :)
There are two mysteries, right?
Mystery 1 could be explained away by cached client JS, but maybe not too. Mystery 2 is a little more interesting, but, since this is dead code, my opinion is that it isn’t worth the (possibly large) effort in solving it.
If someone else disagrees, I think Andy needs more stacktraces from the error logs to look at the code path that is calling this page. Maybe some of them are directly hitting this as a request, but maybe some others are coming from some other less direct code path. I'm not sure how to get him more stacktraces, so if someone wants to help, that's the first thing to do.
If no one really cares so much, then let's just have them deploy the change to remove the code, eh?
Agreed. If it's already code on its way out, let's just finish making it go away. I really don't think it's that interesting of a mystery to keep looking into.
If someone else disagrees, I think Andy needs more stacktraces from the error logs to look at the code path that is calling this page. Maybe some of them are directly hitting this as a request, but maybe some others are coming from some other less direct code path. I'm not sure how to get him more stacktraces, so if someone wants to help, that's the first thing to do.
I don't know what more we need. P289 yesterday showed us it was coming from the expected code path. The description here shows what breaks when that does ($allocContext isn't set in BannerRandom since the refactor, ends up being passed null to BannerChooser). The fix is clearly:
So yes, maybe as an academic exercise it would be nice to understand why it's being called, but I don't think it's worth leaving broken in prod until we do.
If no one really cares so much, then let's just have them deploy the change to remove the code, eh?
Yes, please.
Quick update here: we're preparing a simple patch to just return a 410 from the Special:BannerRandom endpoint. That should be guaranteed to not break anything else. (The patch for fully removing the code is more complicated and needs more careful checking before deployment.)
@chad and @Ottomata thanks so much!
Change 190506 had a related patch set uploaded (by AndyRussG):
Deprecate Special:BannerRandom and return a 410
Change 190559 had a related patch set uploaded (by AndyRussG):
Warn and die at unexplained SpecialBannerRandom execution
Change 190559 merged by jenkins-bot:
Warn in a special log on unexpected code execution
Change 190596 had a related patch set uploaded (by AndyRussG):
Fix detail in warn in a special log on unexpected code execution
Change 190596 merged by jenkins-bot:
Fix detail in warn in a special log on unexpected code execution
We think the spam to hhvm.log is resolved now, it's been almost 2 hours with no more messages. Sorry, kthx bye!
Results from this debug log:
I suppose the above might be interesting if anyone would like to investigate the forever-cached, deprecated JS that is making these calls (mystery no. 1, above).
Regarding mystery no. 2, the unexplained higher prevalence of the error messages in hhvm.log vis-à-vis the number of requests to Special:BannerRandom: it turns out to be explained by mistakes on my part, namely that I thought Varnish made two retries on 503s (it actually does three) and I made a dumb calculation mistake involving disappearing parentheses :(. In other words, no mystery no. 2.
Thanks everyone for your patience with my thickheadedness and slow learning about what to do in this kind of situation. And many thanks to @K4-713, who also made some excellent loggy suggestions.
Unless anyone objects, we'll undeploy the special debug logging at the next opportunity.
@AndyRussG interesting that you're seeing a high prevalence of country=XX. We've gotten a smattering of reports about that, and it happens to me consistently, but on first investigation since the fix for it a few months ago we thought maybe it was a caching issue. Here's the bug about it: T87677
Should we reopen?