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

RESOLVED FIXED in Firefox 49

Status

()

Core
DOM
RESOLVED FIXED
2 years ago
a year ago

People

(Reporter: hallvors, Assigned: bz)

Tracking

(Depends on: 2 bugs)

Trunk
mozilla49
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox49 fixed, fennec+)

Details

(Whiteboard: btpp-followup-2016-05-12, URL)

Attachments

(7 attachments)

(Reporter)

Description

2 years ago
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..)
tracking-fennec: --- → ?
tracking-fennec: ? → +
Component: General → DOM
Product: Firefox for Android → Core
Version: unspecified → Trunk
Boris, what do you think?
Flags: needinfo?(bzbarsky)
Whiteboard: btpp-followup-2016-05-12
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?
Flags: needinfo?(bzbarsky) → needinfo?(markcapella)
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
Flags: needinfo?(markcapella)
Yes, I've done that, and I can't reproduce at all....
Flags: needinfo?(markcapella)
Guess I can add: local m-c build, (v49), vanilla / no patches in queue, restarted in safe mode, "Enable multi-process Nightly" NOT checked.
Flags: needinfo?(markcapella)
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.
Status: NEW → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → INVALID
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.
(Reporter)

Comment 9

2 years ago
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.
(Reporter)

Comment 10

2 years ago
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?
Status: RESOLVED → REOPENED
Flags: needinfo?(bzbarsky)
Resolution: INVALID → ---
Summary: Firing load events twice on some SCRIPT elements breaks Ext.js / Sencha - based bill pay form on securebillpay.net → Firing unexpected load events on SCRIPT elements during sync XHR processing breaks Ext.js / Sencha - based bill pay form on securebillpay.net
Yes, that sounds much more plausible.  ;)

I'll be able take a close look on Monday.  Thank you for minimizing the page!
Created attachment 8754095 [details]
I think this is the most minimal testcase here
Created attachment 8754460 [details] [diff] [review]
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!
Attachment #8754460 - Flags: review?(bugs)
Assignee: nobody → bzbarsky
Status: REOPENED → ASSIGNED
Created attachment 8754461 [details] [diff] [review]
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.
Attachment #8754461 - Flags: review?(bugs)
Created attachment 8754462 [details] [diff] [review]
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.
Attachment #8754462 - Flags: review?(bugs)
Flags: needinfo?(bzbarsky)
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
Attachment #8754460 - Flags: review?(bugs) → review+
Or
bz	smaug: ParserBlockingScriptExecutionBlocker ?

Updated

2 years ago
Attachment #8754461 - Flags: review?(bugs) → review+
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.
Attachment #8754462 - Flags: review?(bugs) → review+
Depends on: 1274733

Comment 20

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/ec2fd25740c8
https://hg.mozilla.org/mozilla-central/rev/88a7fdbd52ba
https://hg.mozilla.org/mozilla-central/rev/81caeffdab2f
Status: ASSIGNED → RESOLVED
Last Resolved: 2 years ago2 years ago
status-firefox49: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla49
Depends on: 1281366
Depends on: 1280091

Updated

a year ago
Depends on: 1333245
You need to log in before you can comment on or make changes to this bug.