Page MenuHomePhabricator

Investigate origin of ResourceLoader requests for private module 'user.tokens' and 'user.options'
Closed, ResolvedPublic

Description

ResourceLoader::respond: request for private module 'user.tokens' denied
ResourceLoader::respond: request for private module 'user.options' denied

About half of these are from third-party referrers and simply hit load.php with modules we no longer support publicly.

However a fair amount actually have production referrers such as:
http://en.wikipedia.org/wiki/List_of_Presidents_of_the_Philippines
https://es.m.wikipedia.org/wiki/Dimebag_Darrell

These private modules are embedded in OutputPage before any module load is triggered. So these shouldn't be possible. Investigate the origin and context of these requests.

Due to the response handling, these requests end up interrupting the dependency state machine. So whatever module ended up needing these will not executing due to missing dependencies. Would likely fail in an incomplete user interface or user-facing error of some kind.

Event Timeline

Krinkle created this task.Jun 9 2015, 3:19 AM
Krinkle raised the priority of this task from to High.
Krinkle updated the task description. (Show Details)
Krinkle added a subscriber: Krinkle.
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJun 9 2015, 3:19 AM

Change 216905 had a related patch set uploaded (by Krinkle):
[WMF] resourceloader: Add logging for T101806 private modules

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

Change 216905 had a related patch set uploaded (by Krinkle):
[WMF] resourceloader: Add logging for T101806 private modules

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

Change 217004 had a related patch set uploaded (by Krinkle):
Log 'resourceloader.forbidden' events with ModuleLoadFailure schema

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

Change 217010 had a related patch set uploaded (by Krinkle):
[WMF] resourceloader: Add logging for T101806 private modules

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

Change 216905 abandoned by Krinkle:
[WMF] resourceloader: Add logging for T101806 private modules

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

Krinkle claimed this task.Jun 9 2015, 4:50 PM
Krinkle moved this task from Inbox to Assigned on the MediaWiki-ResourceLoader board.
Krinkle set Security to None.

Change 217184 had a related patch set uploaded (by Krinkle):
[WMF] resourceloader: Add logging for T101806 private modules

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

Change 217010 merged by jenkins-bot:
[WMF] resourceloader: Add logging for T101806 private modules

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

Change 217184 merged by jenkins-bot:
[WMF] resourceloader: Add logging for T101806 private modules

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

He7d3r added a subscriber: He7d3r.Jun 10 2015, 1:31 AM

Change 217004 merged by Ori.livneh:
Log 'resourceloader.forbidden' events with ModuleLoadFailure schema

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

Change 217535 had a related patch set uploaded (by Krinkle):
Log 'resourceloader.forbidden' events with ModuleLoadFailure schema

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

Change 217535 merged by jenkins-bot:
Log 'resourceloader.forbidden' events with ModuleLoadFailure schema

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

Restricted Application added a subscriber: Mjbmr. · View Herald TranscriptJun 13 2015, 12:17 AM

Change 218016 had a related patch set uploaded (by Krinkle):
Log 'resourceloader.forbidden' events from readers

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

Change 218017 had a related patch set uploaded (by Krinkle):
Log 'resourceloader.forbidden' events from readers

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

Change 218017 merged by jenkins-bot:
Log 'resourceloader.forbidden' events from readers

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

Krinkle added a comment.EditedJun 15 2015, 1:47 PM

The log events captured server-side and sent to logstash only contain HTTP referer as context. The above patch uses client-side tracking in mw.loader to send events to EventLogging. Here are the results from hour period last Saturday evening.

There was a 6 hour window before this during which only logged-in users were tracked but not a single event was logged.

I aggregated the results manually.

eventlogging.filter(schema='ModuleLoadFailure')

Source:
- logged-in users (unsampled)
- logged-out users (1 in 100 page loads)

Start: 1434215736  Sat Jun 13 2015 18:15:36 GMT+0100 (BST)
End:   1434236726  Sun Jun 14 2015 00:05:26 GMT+0100 (BST)

hits: 62

users:
- anon (62)
- logged-in (0)

webHost:
     42 u'en.m.wikipedia.org',
     12 u'ru.m.wikipedia.org',
      4 u'bn.m.wikipedia.org',
      2 u'id.m.wikipedia.org',
      2 u'ar.m.wikipedia.org',

module:
# private module being requested despite being embedded in HTML
- u'user.options' (31)
- u'user.tokens' (31)

request:
# other modules in the same batch that have 'module' as a dependency.
- u'mediawiki.user' (62)

recvFrom:
- cp*.esams.wmnet (46)
- cp*.eqiad.wmnet (16)

userAgent:
- Linux (62)
- Android (62)
      2 Android 2.2.2;
      2 Android 2.2;
      2 Android 2.3.5;
      4 Android 2.3.6;
      2 Android 4.0.4;
      4 Android 4.1.1;
      6 Android 4.1.2;
      1 Android 4.2.1;
     17 Android 4.2.2;
      2 Android 4.3;
     10 Android 4.4.2;
      5 Android 4.4.4;
      3 Android 5.0.2;
      2 Android 5.1.1;
- UCBrowser (62)
      1 UCBrowser/9.9.2
      2 UCBrowser/10.0.0
      2 UCBrowser/10.0.1
      8 UCBrowser/10.0.2
      2 UCBrowser/10.1.0
      6 UCBrowser/10.2.0
      9 UCBrowser/10.3.0
     11 UCBrowser/10.4.1
     19 UCBrowser/10.5.0
      2 UCBrowser/10.5.2

Interesting is that all hits are only from the mobile sites, and only from the UCBrowser on Android.

All requests loaded both "user.options" and "user.tokens" (matches are 50/50 spread, and all in pairs from the same client).

All requests loaded those two modules in the same batch with "mediawiki.user".

The only moduleson en.m.wikipedia.org that depends on user.options is:

["mediawiki.user"]

The only modules on en.m.wikipedia.org that depend on mediawiki.user:

["ext.visualEditor.mediawiki", "ext.visualEditor.mwcore", "mobile.user", "ext.flow.components", "ext.flow.editor"]

The request therefore must be triggered by the client loading either mediawiki.user directly, or through one of the above modules.

In order for such request to trigger broken loading of "user.tokens" or "user.options", the request would have to be made in one of two ways. Either:

  • The page HTML was corrupted or several months old and didn't include the embedded user modules.
  • The page somehow made an mw.loader.load() call before the embedded user modules in the HTML.

[..] In order for such request to trigger broken loading of "user.tokens" or "user.options" [..] Either:

  • The page HTML was corrupted or several months old and didn't include the embedded user modules.
  • The page somehow made an mw.loader.load() call before the embedded user modules in the HTML.

The request response for startup and jquery/mediawiki can't be outdated because it includes the new instrumentation recently added for this task.

The request response for the article HTML can't be outdated because it includes mw.loader.load( ... ext.wikimediaEvents ..); which was only recently introduced.

That would leave corruption of the HTML stream and/or some obscure JavaScript execution bug that would skip certain inline script tags.

Change 218016 merged by jenkins-bot:
Log 'resourceloader.forbidden' events from readers

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

Change 218680 had a related patch set uploaded (by Krinkle):
Log a summary of scripts on the page with ModuleLoadFailure

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

Change 218692 had a related patch set uploaded (by Krinkle):
Log a summary of scripts on the page with ModuleLoadFailure

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

Change 218680 abandoned by Krinkle:
Log a summary of scripts on the page with ModuleLoadFailure

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

Change 218692 abandoned by Krinkle:
Log a summary of scripts on the page with ModuleLoadFailure

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

Krinkle lowered the priority of this task from High to Normal.Jun 17 2015, 2:57 AM

Change 218913 had a related patch set uploaded (by Krinkle):
mw.loader: Omit private modules from the request queue

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

Change 218913 merged by jenkins-bot:
mw.loader: Omit private modules from the request queue

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

Krinkle closed this task as Resolved.Jun 29 2015, 7:06 PM