1267989 - Firing unexpected load events on SCRIPT elements during sync XHR processing breaks Ext.js / Sencha - based bill pay form on securebillpay.net

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[Hallvord R. M. Steen [:hallvors]]

In https://webcompat.com/issues/2406 we've been trying to figure out why the loading animation *most of the time* hangs on this URL. There's some digging in this comment: https://webcompat.com/issues/2406#issuecomment-214362824

The problem appears to be that the site keeps a counter of "pending" modules, and this counter decrements too quickly at some point while modules are loading. When it goes down to 0 and the queue of requirements is empty the script tries to boot but in fact one module is still loading. When the "pending" counter goes to -1 we're actually ready, but the site will only try to boot at the ===0 stage (reasonably enough).

Here's an attempted demo:

http://hallvord.com/temp/moz/bug/wc2406/wc2406.htm

Note how some of the first script elements are logged as having *two* load events fired for that SCRIPT element. I think a rogue load event makes the script decrement the counter once more than expected.

(This seems like core functionality but doesn't happen on desktop..)

Comment 1

[Mark Capella [:capella]]

I see it on desktop, fairly easily, for ex:

https://www.dropbox.com/s/b1pgtgcy21tmwyx/bug_1267989_desktop.png?dl=0

Comment 2

[Andrew Overholt [:overholt]]

Boris, what do you think?

Comment 3

[Boris Zbarsky [:bzbarsky]]

No idea so far.  Mark, if you can reproduce this on desktop on Hallvord's testcase, can you try to figure out what's needed for someone else to reproduce?  For example, does it reproduce for you with a clean profile?

Comment 4

[Mark Capella [:capella]]

I can try with a new profile if you need, but the way I see it with my existing profile is I right-click his link [0] and then select "Open Link in New Tab", switch to the tab, and hit refresh a couple times.

[0] http://hallvord.com/temp/moz/bug/wc2406/wc2406.htm

Comment 5

[Boris Zbarsky [:bzbarsky]]

Yes, I've done that, and I can't reproduce at all....

Comment 6

[Mark Capella [:capella]]

Guess I can add: local m-c build, (v49), vanilla / no patches in queue, restarted in safe mode, "Enable multi-process Nightly" NOT checked.

Comment 7

[Boris Zbarsky [:bzbarsky]]

Thanks.  Disabling e10s allowed me to reproduce.

In the failing case, my console is showing me this:

  inject 0 (loaded: 0 pending: 0, modules registered: 0)
  inject 1 (loaded: 0 pending: 1, modules registered: 0)
  inject 2 (loaded: 0 pending: 2, modules registered: 0)
  inject 0 (loaded: 0 pending: 3, modules registered: 0)
  inject 1 (loaded: 0 pending: 3, modules registered: 0)
  inject 2 (loaded: 0 pending: 3, modules registered: 0)
  inject 3 (loaded: 0 pending: 3, modules registered: 0)
  inject 4 (loaded: 0 pending: 4, modules registered: 0)
  inject 5 (loaded: 0 pending: 5, modules registered: 0)
  inject 6 (loaded: 0 pending: 6, modules registered: 0)
  inject 7 (loaded: 0 pending: 7, modules registered: 0)
  inject 8 (loaded: 0 pending: 8, modules registered: 0)
  onload on 0 [object HTMLScriptElement]
  onload on 1 [object HTMLScriptElement]
  onload on 2 [object HTMLScriptElement]
  onload on 3 [object HTMLScriptElement]
  onload on 4 [object HTMLScriptElement]
  onload on 5 [object HTMLScriptElement]
  DOUBLE LOAD Module1
  onload on 1 [object HTMLScriptElement]
  DOUBLE LOAD Module0
  onload on 0 [object HTMLScriptElement]
  DOUBLE LOAD Module2
  onload on 2 [object HTMLScriptElement]
  onload on 6 [object HTMLScriptElement]
  onload on 7 [object HTMLScriptElement]
  onload on 8 [object HTMLScriptElement]

and the actual web page shows module0.js, module1.js, module2.js as the filenames that got two load events.  Based on the log above, they got two load events because they got injected twice!

So why did they get injected twice?  Careful reading of the script says it's because the script is broken.  It starts loads from two places: the loadInterval timer callback and toplevel script.  The loadInterval timer callback has two modes: call injectScript immediately, or add "load" event listeners to the window that will do the injectScript calls; it uses the former if the load event has already fired.  The toplevel script always adds "load" listeners to the window.

These pending load listeners are not counted in modulesLoaded (because they're not loaded) and are not present in pendingFiles (because they haven't made their injectScript calls yet, and that's what adds things to pendingFiles).

OK, so now what happens?  The script runs.  It sets up the loadInterval timer for 4ms, and adds load listeners to injectScript(0), injectScript(1), and injectScript(2).  Now we have a race.  If the page load event fires before the interval timer, loads 0, 1, 2, will get started.  Then the interval timer fires, sees 3 things in pendingFiles, and starts with injectScript(3), calling it directly because page "load" has already fired.  On the other hand, if the interval timer fires before the page load event, it will see that modulesLoaded == 0 and pendingFiles has nothing, and will go ahead and start with adding load listeners to call injectScript(0), injectScripts(1), injectScript(2).  If it manages to fire _again_ before page load fires, it'll queue those same three loads _again_.

Anyway, the behavior observed here is certainly not a Gecko bug.  We're just doing what the buggy script asked for.

Comment 8

[Boris Zbarsky [:bzbarsky]]

Actually, please reopen if that script is not an accurate reduction of the original page.  As I just said in https://webcompat.com/issues/2406#issuecomment-217342440 the issue might be reentry under sync XHR confusing the state logic on the page, if the sync XHR codepaths are being hit.

Comment 9

[Hallvord R. M. Steen [:hallvors]]

I'm following up the analysis in the webcompat issue - seems like a piece of Ext.js that is prone to race conditions, but I will reopen this one if I find something we should fix.

Comment 10

[Hallvord R. M. Steen [:hallvors]]

Think I've found it this time: Gecko does a relatively poor job at blocking other scripts from running while processing sync XHR requests.. I'm working on a new demo at http://hallvord.com/temp/moz/bug/wc2406/wc2406b.htm - Boris, now we're closing in on a real issue, right?

Comment 11

[Boris Zbarsky [:bzbarsky]]

Yes, that sounds much more plausible.  ;)

I'll be able take a close look on Monday.  Thank you for minimizing the page!

Comment 12

[Boris Zbarsky [:bzbarsky]]

Attachment: I think this is the most minimal testcase here

Comment 13

[Boris Zbarsky [:bzbarsky]]

Attachment: part 1. Rename nsScriptLoader::Add/RemoveExecuteBlocker to Add/RemoveParserBlockingScriptBlocker, to more clearly reflect what it does

If you have better naming suggestions, please let me know!

Comment 14

[Boris Zbarsky [:bzbarsky]]

Attachment: part 2. Add nsScriptLoader::Add/RemoveExecuteBlocker which in fact block script execution on that script loader

Unlike the parser-blocking thing, we don't need to block parents or anything; all consumers of this API will be walking the frame tree anyway.

Comment 15

[Boris Zbarsky [:bzbarsky]]

Attachment: part 3. Make suppressing event handling on a document also block script execution for that document

Note that we do this here instead of when we suspend timeouts, because it makes
it simpler to handle situations in which a window's document changes while
things are suspended/blocked.

The nsDocumentViewer.cpp is not strictly needed, but avoids some extraneous
calls to SuppressEventHandling with a 0 suppression count.

Comment 16

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8754460 [details] [diff] [review]
part 1.  Rename nsScriptLoader::Add/RemoveExecuteBlocker to Add/RemoveParserBlockingScriptBlocker, to more clearly reflect what it does

>-   * Add/remove blocker. Blockers will stop scripts from executing, but not
>-   * from loading.
>+   * Add/remove a blocker for parser-blocking scripts (and XSLT
>+   * scripts). Blockers will stop such scripts from executing, but not from
>+   * loading.
>    */
>-  void AddExecuteBlocker()
>+  void AddParserBlockingScriptBlocker()

Because of *ScriptBlocker suffix, could you add a comment that this does *not* have anything to do with 
AddScriptBlocker

Comment 17

[Olli Pettay [:smaug][[e-mail]]]

Or
bz	smaug: ParserBlockingScriptExecutionBlocker ?

Comment 18

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8754462 [details] [diff] [review]
part 3.  Make suppressing event handling on a document also block script execution for that document

yup, looks as simple as what I was hoping. Thanks.

Comment 19

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/ec2fd25740c8
https://hg.mozilla.org/integration/mozilla-inbound/rev/88a7fdbd52ba
https://hg.mozilla.org/integration/mozilla-inbound/rev/81caeffdab2f

Comment 20

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/ec2fd25740c8
https://hg.mozilla.org/mozilla-central/rev/88a7fdbd52ba
https://hg.mozilla.org/mozilla-central/rev/81caeffdab2f

Comment 21

[Olli Pettay [:smaug][[e-mail]]]

Try push for beta patches, includes patch for bug 1281366 too.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=013b02f3db602a8f095c9223020342584e3fd376

Comment 22

[Olli Pettay [:smaug][[e-mail]]]

Attachment: part1_beta

Comment 23

[Olli Pettay [:smaug][[e-mail]]]

Attachment: part2_beta

Comment 24

[Olli Pettay [:smaug][[e-mail]]]

Attachment: part3_beta