Certain firewalls / proxies strip CORS Allow-Origin headers (example); measure how many users are affected by this:
Results: CORS-enabled loading of script files causes loading failure in about 0.1%-0.15% of the sampled pageviews.
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Declined | None | T106915 Use Sentry in production | |||
| Declined | Tgr | T91649 Deploy Sentry (JavaScript error logging) to production, configured to log only a limited subset of users/pages | |||
| Resolved | • jlinehan | T88399 Improve Javascript error logging coverage | |||
| Declined | None | T382 RfC: Server-side Javascript error logging | |||
| Open | None | T508 Use CORS-enabled fetch of scripts to avoid same-domain limitations in JS error logging | |||
| Resolved | Tgr | T507 Measure how many users have CORS-hostile proxies |
Change 182762 had a related patch set uploaded (by Gergő Tisza):
Refactor code to be more modular
Change 182765 had a related patch set uploaded (by Gergő Tisza):
Enable CORS logging in ImageMetrics vagrant role
Change 182766 had a related patch set uploaded (by Gergő Tisza):
Measure CORS script loading support
Change 182767 had a related patch set uploaded (by Gergő Tisza):
Enable CORS support logging on beta
Change 182765 merged by jenkins-bot:
Enable CORS logging in ImageMetrics vagrant role
See https://wikitech.wikimedia.org/wiki/EventLogging/Testing/BetaLabs. Currently they are not reported properly due to https://gerrit.wikimedia.org/r/#/c/194008/.
Change 194008 had a related patch set uploaded (by Gergő Tisza):
Fix typo in CorsLogger
mysql> select webHost, sum(event_scriptLoaded) / count(*) successful, count(*) total from ImageMetricsCorsSupport_10884476 where event_xhrSupported and event_scriptAttributeSupported and timestamp > '20150305033000' group by webHost order by webHost; +---------------------------------------+------------+-------+ | webHost | successful | total | +---------------------------------------+------------+-------+ | 127.0.0.1 | 0.6579 | 76 | | aa.wikipedia.beta.wmflabs.org | 1.0000 | 1 | | commons.wikimedia.beta.wmflabs.org | 0.7890 | 839 | | de.wikipedia.beta.wmflabs.org | 0.9495 | 99 | | deployment.wikimedia.beta.wmflabs.org | 1.0000 | 27 | | en.m.wikipedia.beta.wmflabs.org | 0.8021 | 2719 | | en.wikibooks.beta.wmflabs.org | 1.0000 | 1 | | en.wikipedia.beta.wmflabs.org | 0.7601 | 3268 | | es.wikipedia.beta.wmflabs.org | 1.0000 | 5 | | simple.wikipedia.beta.wmflabs.org | 1.0000 | 35 | | test.m.wikipedia.beta.wmflabs.org | 0.0000 | 2 | | wikidata.beta.wmflabs.org | 0.0255 | 784 | +---------------------------------------+------------+-------+
CORS success ratio should be 100% or very close to that, so something is still wrong.
Nothing jumps out from the domain or UA distribution of the failures.
Maybe you got the cutoff time for the typo fix merge wrong? See:
select webHost, sum(event_scriptLoaded) / count(*) successful, count(*) total from ImageMetricsCorsSupport_10884476 where event_xhrSupported and event_scriptAttributeSupported and timestamp > '20150306000000' group by webHost order by webHost; 127.0.0.1 0.9819 166 aa.wikipedia.beta.wmflabs.org 1.0000 1 commons.wikimedia.beta.wmflabs.org 1.0000 1149 de.wikipedia.beta.wmflabs.org 1.0000 99 deployment.wikimedia.beta.wmflabs.org 1.0000 37 en.m.wikipedia.beta.wmflabs.org 0.9994 3397 en.wikibooks.beta.wmflabs.org 1.0000 1 en.wikipedia.beta.wmflabs.org 1.0000 4138 es.wikipedia.beta.wmflabs.org 1.0000 4 simple.wikipedia.beta.wmflabs.org 1.0000 3 test.m.wikipedia.beta.wmflabs.org 0.0000 2 test.wikipedia.beta.wmflabs.org 0.0000 4 wikidata.beta.wmflabs.org 0.0550 636
Thanks! I was stupidly assuming that the timestamps I see in Gerrit are UTC, but they were of course localized.
It's curious that it does not work at all in Wikidata beta, but in itself that's not particularly troubling. I'll enable this live during the next SWAT then.
Change 195440 had a related patch set uploaded (by Gergő Tisza):
Fix typo in CorsLogger
Change 195441 had a related patch set uploaded (by Gergő Tisza):
Fix typo in CorsLogger
I'll leave this running a bit more, but seems like the ratio of failed loads is around 0.4% which is rather higher than I expected.
I'd like to do a sanity check first - do a non-CORS load at the same time as the CORS load, and see how often that fails. I find it hard to believe that half percent of users would be behind CORS-stripping firewalls.
Change 200118 had a related patch set uploaded (by Gergő Tisza):
Add a sanity check to the CORS test
Change 200896 had a related patch set uploaded (by Gergő Tisza):
Add a sanity check to the CORS test
mysql:research@analytics-store.eqiad.wmnet [log]> select sum(event_xhrSupported and event_scriptAttributeSupported and !event_scriptLoaded) / count(*) cors_blocked, sum(event_xhrSupported and event_scriptAttributeSupported and event_sanityCheck and !event_scriptLoaded) / count(*) sane_cors_blocked, sum(event_xhrSupported and event_scriptAttributeSupported and !event_sanityCheck) / count(*) normal_load_failed_supported, sum(!event_sanityCheck) / count(*) normal_load_failed_all, count(*) total from ImageMetricsCorsSupport_11686678; +--------------+-------------------+------------------------------+------------------------+--------+ | cors_blocked | sane_cors_blocked | normal_load_failed_supported | normal_load_failed_all | total | +--------------+-------------------+------------------------------+------------------------+--------+ | 0.0040 | 0.0029 | 0.0070 | 0.0090 | 220805 | +--------------+-------------------+------------------------------+------------------------+--------+
(legend: cors_blocked - doing a CORS-enabled load for a test script failed; normal_load_failed_supported - doing a normal (non-CORS-enabled) load for a test script failed (browsers not supporting CORS are not counted); normal_load_failed_all - same but all browsers are counted; sane_cors_blocked - normal load worked but CORS-enabled load failed)
That is,
The 0.4% number is consistent with the data logged for the previous schema version and remarkably stable over time.
If the failure is purely to random network conditions, I would expect cors_blocked ~= normal_load_failed_supported and sane_cors_blocked ~= cors_blocked * (1-normal_load_failed_supported). If enabling CORS for a script load can directly cause it to fail, I would expect cors_blocked > normal_load_failed_supported and sane_cors_blocked > cors_blocked * (1-normal_load_failed_supported) (which I think would loosely mean that load failure is positively correlated with CORS being enabled). In contrast, it seems like enabling CORS would make the requests actually fail less often. I would appreciate a review from Analytics to make sure my logic is sound.
From a technical perspective, possible problems I can think of:
Change 203348 had a related patch set uploaded (by Gergő Tisza):
Fix some potential sources of bias for CORS logging
Change 203348 merged by jenkins-bot:
Fix some potential sources of bias for CORS logging
Beta is throwing [ImageMetricsCorsSupport] Missing or empty schema errors. The code seems valid so for now I'm going to assume this some weird side effect of the beta breakage that's going on now.
mysql:research@analytics-store.eqiad.wmnet [log]> select sum(event_xhrSupported and event_scriptAttributeSupported and !event_scriptLoaded) / count(*) cors_blocked, sum(event_xhrSupported and event_scriptAttributeSupported and event_sanityCheck and !event_scriptLoaded) / count(*) sane_cors_blocked, sum(event_xhrSupported and event_scriptAttributeSupported and !event_sanityCheck) / count(*) normal_load_failed_supported, sum(!event_sanityCheck) / count(*) normal_load_failed_all, count(*) total from ImageMetricsCorsSupport_11686678 where timestamp > '20150500000000'; +--------------+-------------------+------------------------------+------------------------+----------+ | cors_blocked | sane_cors_blocked | normal_load_failed_supported | normal_load_failed_all | total | +--------------+-------------------+------------------------------+------------------------+----------+ | 0.0026 | 0.0013 | 0.0015 | 0.0021 | 36416393 | +--------------+-------------------+------------------------------+------------------------+----------+ 1 row in set (3 min 28.46 sec) mysql:research@analytics-store.eqiad.wmnet [log]> select substr(timestamp, 1, 7) batch, sum(event_xhrSupported and event_scriptAttributeSupported and !event_scriptLoaded) / count(*) cors_blocked, sum(event_xhrSupported and event_scriptAttributeSupported and event_sanityCheck and !event_scriptLoaded) / count(*) sane_cors_blocked, sum(event_xhrSupported and event_scriptAttributeSupported and !event_sanityCheck) / count(*) normal_load_failed_supported, sum(!event_sanityCheck) / count(*) normal_load_failed_all, count(*) total from ImageMetricsCorsSupport_11686678 group by batch order by batch desc; +---------+--------------+-------------------+------------------------------+------------------------+---------+ | batch | cors_blocked | sane_cors_blocked | normal_load_failed_supported | normal_load_failed_all | total | +---------+--------------+-------------------+------------------------------+------------------------+---------+ | 2015081 | 0.0028 | 0.0016 | 0.0013 | 0.0019 | 765412 | | 2015080 | 0.0026 | 0.0015 | 0.0013 | 0.0019 | 2991837 | | 2015073 | 0.0025 | 0.0015 | 0.0011 | 0.0017 | 716456 | | 2015072 | 0.0026 | 0.0015 | 0.0012 | 0.0018 | 3725082 | | 2015071 | 0.0025 | 0.0014 | 0.0012 | 0.0017 | 3435098 | | 2015070 | 0.0028 | 0.0015 | 0.0014 | 0.0020 | 2117696 | | 2015063 | 0.0026 | 0.0016 | 0.0011 | 0.0017 | 203508 | | 2015062 | 0.0027 | 0.0014 | 0.0014 | 0.0019 | 2917355 | | 2015061 | 0.0027 | 0.0013 | 0.0016 | 0.0022 | 3540522 | | 2015060 | 0.0023 | 0.0011 | 0.0015 | 0.0022 | 3272449 | | 2015053 | 0.0021 | 0.0008 | 0.0016 | 0.0021 | 728482 | | 2015052 | 0.0023 | 0.0011 | 0.0015 | 0.0021 | 4100134 | | 2015051 | 0.0029 | 0.0012 | 0.0021 | 0.0027 | 4270714 | | 2015050 | 0.0025 | 0.0012 | 0.0015 | 0.0021 | 3713002 | | 2015043 | 0.0038 | 0.0023 | 0.0018 | 0.0025 | 294719 | | 2015042 | 0.0036 | 0.0026 | 0.0012 | 0.0019 | 4233369 | | 2015041 | 0.0032 | 0.0024 | 0.0013 | 0.0020 | 4315902 | | 2015040 | 0.0031 | 0.0022 | 0.0022 | 0.0031 | 3183577 | +---------+--------------+-------------------+------------------------------+------------------------+---------+ 18 rows in set (2 min 31.16 sec)
mysql:research@analytics-store.eqiad.wmnet [log]> select substr(timestamp, 1, 7) batch, sum(event_xhrSupported and event_scriptAttributeSupported and event_sanityCheck and !event_scriptLoaded) / count(*) only_cors_failed, sum(event_xhrSupported and event_scriptAttributeSupported and !event_sanityCheck and event_scriptLoaded) / count(*) only_normal_failed, sum(event_xhrSupported and event_scriptAttributeSupported and !event_sanityCheck and !event_scriptLoaded) / count(*) both_failed, count(*) total from ImageMetricsCorsSupport_11686678 group by batch order by batch desc; +---------+------------------+--------------------+-------------+---------+ | batch | only_cors_failed | only_normal_failed | both_failed | total | +---------+------------------+--------------------+-------------+---------+ | 2015081 | 0.0016 | 0.0001 | 0.0012 | 784970 | | 2015080 | 0.0015 | 0.0001 | 0.0012 | 2991837 | | 2015073 | 0.0015 | 0.0001 | 0.0010 | 716456 | | 2015072 | 0.0015 | 0.0001 | 0.0011 | 3725082 | | 2015071 | 0.0014 | 0.0001 | 0.0011 | 3435098 | | 2015070 | 0.0015 | 0.0002 | 0.0012 | 2117696 | | 2015063 | 0.0016 | 0.0001 | 0.0010 | 203508 | | 2015062 | 0.0014 | 0.0001 | 0.0013 | 2917355 | | 2015061 | 0.0013 | 0.0002 | 0.0014 | 3540522 | | 2015060 | 0.0011 | 0.0003 | 0.0012 | 3272449 | | 2015053 | 0.0008 | 0.0003 | 0.0013 | 728482 | | 2015052 | 0.0011 | 0.0003 | 0.0012 | 4100134 | | 2015051 | 0.0012 | 0.0003 | 0.0018 | 4270714 | | 2015050 | 0.0012 | 0.0003 | 0.0012 | 3713002 | | 2015043 | 0.0023 | 0.0003 | 0.0015 | 294719 | | 2015042 | 0.0026 | 0.0003 | 0.0009 | 4233369 | | 2015041 | 0.0024 | 0.0004 | 0.0009 | 4315902 | | 2015040 | 0.0022 | 0.0014 | 0.0009 | 3183577 | +---------+------------------+--------------------+-------------+---------+ 18 rows in set (2 min 2.76 sec) mysql:research@analytics-store.eqiad.wmnet [log]> select sum(event_xhrSupported and event_scriptAttributeSupported and event_sanityCheck and !event_scriptLoaded) / count(*) only_cors_failed, sum(event_xhrSupported and event_scriptAttributeSupported and !event_sanityCheck and event_scriptLoaded) / count(*) only_normal_failed, sum(event_xhrSupported and event_scriptAttributeSupported and !event_sanityCheck and !event_scriptLoaded) / count(*) both_failed, count(*) total from ImageMetricsCorsSupport_11686678; +------------------+--------------------+-------------+----------+ | only_cors_failed | only_normal_failed | both_failed | total | +------------------+--------------------+-------------+----------+ | 0.0016 | 0.0003 | 0.0012 | 48545272 | +------------------+--------------------+-------------+----------+ 1 row in set (1 min 52.14 sec)
The results look sane now, and fairly stable over time.
Loading a script via CORS fails about 0.25% of the time. About half of that seems to be normal network error and the rest (0.1%-0.15% of all script loads) is genuine failure caused by enabling CORS.
A sanity check where percentages are calculated over all browsers, not just CORS-supporting ones, does not show significantly different data.
@Tgr, you should publish this on the blog or something. I'm sure there are other parties out there who would be interested in such a relatively difficult to discover metric.
Geographic distribution of the failure rate:
mysql:research@analytics-store.eqiad.wmnet [log]> select event_country, sum(event_xhrSupported and event_scriptAttributeSupported and event_sanityCheck and !event_scriptLoaded) / count(*) cors_failed, sum(event_xhrSupported and event_scriptAttributeSupported and !event_sanityCheck and event_scriptLoaded) / count(*) normal_load_failed, sum(event_xhrSupported and event_scriptAttributeSupported and !event_sanityCheck and !event_scriptLoaded) / count(*) both_failed, count(*) total from ImageMetricsCorsSupport_11686678 where timestamp > '20150500000000' group by event_country having total > 10000 order by cors_failed desc; +---------------+-------------+--------------------+-------------+---------+ | event_country | cors_failed | normal_load_failed | both_failed | total | +---------------+-------------+--------------------+-------------+---------+ | CN | 0.0101 | 0.0009 | 0.0020 | 138618 | | SG | 0.0050 | 0.0002 | 0.0015 | 155458 | | NP | 0.0043 | 0.0003 | 0.0015 | 13738 | | AO | 0.0042 | 0.0005 | 0.0021 | 25547 | | IN | 0.0041 | 0.0011 | 0.0020 | 1111184 | | KE | 0.0039 | 0.0006 | 0.0018 | 18775 | | PY | 0.0038 | 0.0002 | 0.0019 | 24470 | | IR | 0.0038 | 0.0006 | 0.0026 | 175855 | | PH | 0.0037 | 0.0005 | 0.0017 | 310588 | | BD | 0.0032 | 0.0003 | 0.0030 | 37023 | | KG | 0.0031 | 0.0002 | 0.0011 | 10634 | | LK | 0.0031 | 0.0002 | 0.0022 | 25004 | | MY | 0.0031 | 0.0003 | 0.0017 | 184671 | | BO | 0.0031 | 0.0006 | 0.0019 | 35043 | | PK | 0.0031 | 0.0003 | 0.0017 | 104172 | | VE | 0.0028 | 0.0005 | 0.0017 | 166700 | | MA | 0.0027 | 0.0006 | 0.0031 | 69065 | | ID | 0.0027 | 0.0008 | 0.0026 | 293828 | | NG | 0.0027 | 0.0005 | 0.0017 | 33694 | | PE | 0.0026 | 0.0002 | 0.0012 | 194185 | | UZ | 0.0026 | 0.0002 | 0.0009 | 12904 | | AR | 0.0026 | 0.0003 | 0.0014 | 390127 | | KZ | 0.0025 | 0.0002 | 0.0014 | 94193 | | EU | 0.0025 | 0.0001 | 0.0006 | 37641 | | SA | 0.0024 | 0.0005 | 0.0013 | 135050 | | EG | 0.0024 | 0.0004 | 0.0023 | 79038 | | GH | 0.0022 | 0.0005 | 0.0024 | 10342 | | EC | 0.0022 | 0.0002 | 0.0014 | 103890 | | CL | 0.0022 | 0.0003 | 0.0012 | 216712 | | BR | 0.0021 | 0.0003 | 0.0013 | 832546 | | TH | 0.0021 | 0.0003 | 0.0015 | 193214 | | NULL | 0.0021 | 0.0003 | 0.0012 | 749529 | | VN | 0.0020 | 0.0003 | 0.0015 | 139900 | | CO | 0.0020 | 0.0002 | 0.0012 | 389164 | | NI | 0.0020 | 0.0001 | 0.0019 | 13779 | | HN | 0.0020 | 0.0003 | 0.0012 | 23235 | | PA | 0.0020 | 0.0003 | 0.0010 | 37763 | | IQ | 0.0019 | 0.0005 | 0.0020 | 24825 | | TN | 0.0019 | 0.0003 | 0.0015 | 30347 | | DZ | 0.0019 | 0.0003 | 0.0022 | 57663 | | TT | 0.0019 | 0.0003 | 0.0007 | 11699 | | CR | 0.0018 | 0.0002 | 0.0012 | 40779 | | ZA | 0.0018 | 0.0004 | 0.0014 | 97369 | | DO | 0.0017 | 0.0003 | 0.0013 | 50883 | | AM | 0.0017 | 0.0001 | 0.0010 | 20537 | | SV | 0.0016 | 0.0003 | 0.0015 | 28650 | | NZ | 0.0016 | 0.0001 | 0.0011 | 126594 | | AZ | 0.0016 | 0.0003 | 0.0018 | 32169 | | KW | 0.0016 | 0.0002 | 0.0012 | 26160 | | MD | 0.0016 | 0.0000 | 0.0008 | 22341 | | UY | 0.0016 | 0.0001 | 0.0012 | 42569 | | TW | 0.0015 | 0.0001 | 0.0019 | 436360 | | PR | 0.0015 | 0.0002 | 0.0012 | 27514 | | BY | 0.0015 | 0.0001 | 0.0011 | 98798 | | MX | 0.0015 | 0.0002 | 0.0011 | 718742 | | HK | 0.0015 | 0.0001 | 0.0015 | 228772 | | GE | 0.0015 | 0.0000 | 0.0014 | 29403 | | IL | 0.0014 | 0.0002 | 0.0011 | 209222 | | | 0.0014 | 0.0002 | 0.0024 | 650920 | | GT | 0.0014 | 0.0002 | 0.0017 | 60804 | | AU | 0.0014 | 0.0001 | 0.0011 | 671303 | | MO | 0.0013 | 0.0003 | 0.0019 | 10201 | | LB | 0.0013 | 0.0000 | 0.0015 | 19607 | | MT | 0.0013 | 0.0000 | 0.0014 | 11138 | | QA | 0.0013 | 0.0002 | 0.0010 | 21470 | | BH | 0.0013 | 0.0001 | 0.0021 | 11166 | | JM | 0.0012 | 0.0005 | 0.0018 | 10016 | | TR | 0.0012 | 0.0002 | 0.0012 | 413053 | | CY | 0.0012 | 0.0000 | 0.0014 | 13647 | | AL | 0.0012 | 0.0002 | 0.0013 | 19841 | | AE | 0.0012 | 0.0001 | 0.0014 | 91377 | | OM | 0.0012 | 0.0001 | 0.0016 | 13460 | | KR | 0.0012 | 0.0001 | 0.0013 | 271081 | | RU | 0.0012 | 0.0001 | 0.0011 | 1689406 | | JO | 0.0011 | 0.0002 | 0.0017 | 21771 | | UA | 0.0011 | 0.0002 | 0.0011 | 419813 | | US | 0.0010 | 0.0002 | 0.0007 | 7814344 | | GR | 0.0010 | 0.0002 | 0.0017 | 147690 | | BA | 0.0010 | 0.0001 | 0.0019 | 32261 | | CA | 0.0010 | 0.0001 | 0.0008 | 1058421 | | ES | 0.0010 | 0.0002 | 0.0024 | 732602 | | PT | 0.0009 | 0.0001 | 0.0015 | 124463 | | IT | 0.0009 | 0.0001 | 0.0015 | 1326534 | | RS | 0.0009 | 0.0002 | 0.0017 | 94075 | | FR | 0.0009 | 0.0002 | 0.0020 | 1363788 | | HU | 0.0008 | 0.0001 | 0.0014 | 131021 | | RO | 0.0008 | 0.0002 | 0.0018 | 132960 | | LV | 0.0008 | 0.0002 | 0.0011 | 31394 | | EE | 0.0008 | 0.0001 | 0.0012 | 34372 | | BG | 0.0008 | 0.0001 | 0.0014 | 87708 | | CZ | 0.0008 | 0.0001 | 0.0011 | 185918 | | IS | 0.0007 | 0.0003 | 0.0010 | 11456 | | DE | 0.0007 | 0.0002 | 0.0027 | 2154068 | | IE | 0.0007 | 0.0001 | 0.0011 | 137305 | | PL | 0.0007 | 0.0002 | 0.0019 | 684941 | | HR | 0.0007 | 0.0002 | 0.0015 | 78135 | | SK | 0.0007 | 0.0002 | 0.0017 | 59113 | | MK | 0.0007 | 0.0001 | 0.0017 | 19895 | | JP | 0.0006 | 0.0001 | 0.0007 | 3298047 | | FI | 0.0006 | 0.0001 | 0.0009 | 214256 | | GB | 0.0006 | 0.0001 | 0.0008 | 2050118 | | SE | 0.0006 | 0.0001 | 0.0009 | 357772 | | SI | 0.0006 | 0.0001 | 0.0014 | 38968 | | NO | 0.0006 | 0.0001 | 0.0010 | 154703 | | AT | 0.0005 | 0.0001 | 0.0013 | 249389 | | NL | 0.0005 | 0.0001 | 0.0009 | 438087 | | LT | 0.0005 | 0.0002 | 0.0014 | 43145 | | LU | 0.0005 | 0.0001 | 0.0006 | 17643 | | BE | 0.0005 | 0.0001 | 0.0010 | 238966 | | CH | 0.0004 | 0.0001 | 0.0009 | 253862 | | DK | 0.0004 | 0.0001 | 0.0009 | 145021 | +---------------+-------------+--------------------+-------------+---------+ 111 rows in set (3 min 35.59 sec)