Bugzilla

Comment 2

•

8 years ago

Is it at all possible to provide either a link to the page involved or at least the actual files involved?

Do you have any addons?  If so, do you see the behavior if you turn them off?

In general, looking at the script loader, there is a queue of deferred requests, things get added to it when the relevant <script> element is parsed, and only the first element of the queue can run.  So it's hard to see how things can get out of order here...

Have you tried adding console.log() calls to both files and seeing what order those appear in when you run into the undefined objects problem?  Are they out of order in that case, or in order?

Updated

•

8 years ago

Flags: needinfo?(nstoddar74)

Comment 3

•

8 years ago

I am seeing the same issue in Firefox 42.0.1 for Android.

Comment 4

•

8 years ago

Same questions as comment 2.

Flags: needinfo?(simon.g.flowers)

Comment 5

•

8 years ago

(In reply to Boris Zbarsky [:bz] from comment #4)
> Same questions as comment 2.

Unfortunately I'm unable to provide a link to the page or post source code (it's a work project).

The only addon I had running was "OpenH264 Video Codec provided by Cisco Systems, Inc. 1.4". I disabled this and am no longer able to reproduce the issue (even after re-enabling it).

Flags: needinfo?(simon.g.flowers)

Comment 6

•

8 years ago

OK.  That ... does make it hard to make progress here.  :(

Comment 7

•

8 years ago

This started occurring again, and I noticed it only seems to happen when I have the WebIDE remote debugger attached.

I updated my desktop Firefox to 43.0b7, as I was previously using a desktop build older than the mobile build, and was getting the "connected runtime has a more recent build date" warning. The issue still occurred in the newer version.

My index.html looks something like this:

<!DOCTYPE html>

<html lang="en">
<head>
    <meta charset="utf-8" />
    <meta content='width=device-width, initial-scale=1.0, maximum-scale=1.0, user-scalable=0' name='viewport' />
    <title>example</title>
    <link rel="stylesheet" href="[style1]" type="text/css" />
    <link rel="stylesheet" href="[style2]" type="text/css" />
</head>
<body>
    ...other scripts
    <script type="text/javascript" src="libs/ractive.js" defer></script>
    <script type="text/javascript" src="[lib dependent on ractive]" defer></script>
    <script type="text/javascript" src="jquery.min.js" defer></script>
    ...other scripts
    <script type="text/javascript" src="[lib dependent on jquery]" defer></script>
    ...other scripts
</body>
</html>

Sometimes I would get "$ is undefined" errors in [lib dependent on jquery]. Sometimes "Ractive is undefined" in [lib dependent on ractive]. Other times everything would work fine. These all seemed to have an equal-ish chance of occurring once it had initially occurred. Adding a console.log into ractive or jquery had the expected output - printed after the errors if they occurred.

I have since disabled the plugin mentioned above again, and it's stopped occurring again.

Comment 8

•

8 years ago

Ignore my comments regarding toggling the plugin causing the issue to stop occurring - this no longer seems to be the case.

Comment 9

•

8 years ago

> Adding a console.log into ractive or jquery had the expected output - printed after the
> errors if they occurred.

So the console.logs happened in the right order, but you still got those "something is undefined" exceptions?

It would be _really_ helpful to have a way to actually reproduce this...  Do you see the problem in a clean profile?

admin

Comment 10

•

8 years ago

I can confirm the same. You can easily replicate it on http://goo.gl/kIHG
When visiting page for the first time deferred scripts load in the correct order. On reload it RANDOMLY fails to do so.

Comment 11

•

8 years ago

Sorry for the lag here; I was on vacation.

Using the link from comment 10, how do I tell whether the scripts ran in the right order or not?

Flags: needinfo?(admin)

mitashkyster

Comment 12

•

8 years ago

Hi guys,

I was able to reproduce this issue. Using 2 js files.
My observations are that this happen only when you have the first file loaded from the cache, First file is relatively large and you have Firebug addon activated.

I was not able to reproduce the issue with Firebug disabled.

Hope this helps.

Andrey

Comment 13

•

8 years ago

I have seen this bug few months ago, and it is still present after this time.
My current version of FF is 44.0.2.
Best of all this bug shows after refreshing a page without loading from cache.
Without "defer" attribute everything works fine.

mitashkyster

Comment 14

•

8 years ago

Hi Andrey,

Are you using Firebug? If yes, are you able to reproduce this issue with Firebug Plugin uninstalled?

Regards

Comment 15

•

8 years ago

For what it's worth, I've been trying to reproduce this bug, using the following steps:

1)  Create a new profile, install Firebug.
2)  Create a web page like this:

  <script>                                                                             
  var x = 2;                                                                           
  onload = function() { document.body.textContent = x; }                               
  </script>
  <script defer src="test1.js"></script>
  <script defer src="test2.js"></script>

where test1.js is the line "x = x + 3;" followed by 100KB or so of padding comment, and test2.js is the line "x = x + 3;".  I expect this to show "25" if the scripts ran in order and 13 if they ran our of order.  So far it comes up 25 every time...  I did verify that the first (large) script is getting a "304 not modified" from the server and is then being read from cache.

I have tried enabling the Net and Script panels in Firebug, which are disabled by default, and I still get 25 every time...

I could _really_ use a hand reproducing this.  :(

Flags: needinfo?(mitashkyster)

Comment 16

•

8 years ago

Er, I meant: test2.js is the line "x = x * 5;" of course.  Otherwise one does not get 25.  ;)

mitashkyster

Comment 17

•

8 years ago

Hi Boris.

Try this:
1. Install Firebug, and enable it.
2. Install user agent control plugin e. g. https://addons.mozilla.org/en-US/firefox/addon/user-agent-overrider/
3. Have UA string from a phone - e. g. "Chrome 40: Mozilla/5.0 (Linux; Android 5.1.1; Nexus 4 Build/LMY48T) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/40.0.2214.89 Mobile Safari/537.36"
4. Open direct.asda.com (you shouldn't be redirected to m.direct.asda.com)
5. Navigate to http://direct.asda.com/george/mens-clothing/D2,default,sc.html
6. Look at the the Firebug console: "ReferenceError: jQuery is not defined" can be seen

I think it happens only if you have js files cached.

Regards

Flags: needinfo?(mitashkyster)

Comment 18

•

8 years ago

Thank you!  With those steps (and making sure the Script panel in Firebug is activated), I can reproduce in an optimized build.  Sadly, I can't reproduce in a debug build, because it's somewhat timing-dependent.  But the optimized build is enough to figure out what's up.

Here's what's going on.  The script loader has this loop in nsScriptLoader::ProcessPendingRequests:

1213      if (mDocumentParsingDone && mXSLTRequests.isEmpty()) {
1214        while (!mDeferRequests.isEmpty() && mDeferRequests.getFirst()->IsReadyToRun()) {
1215          request = mDeferRequests.StealFirst();
1216          ProcessRequest(request);
1217        }
1218      }

Note that request is removed from mDeferRequests before we call ProcessRequest.

Now say we have two deferred scripts.  The first one finishes loading and calls into ProcessPendingRequests but the second hasn't finished loading yet.  We call ProcessRequest on it, and go to compile the script.  Under script compilation, the JS engine calls js::Debugger::fireNewScript which calls out into Firebug's "new script" handler.  Firebug JS then runs, with this stack:

0 EventLoop.prototype.enter() ["resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/script.js":347]
    this = [object Object]
1 ThreadActor.prototype.unsafeSynchronize(aPromise = [object Object]) ["resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/script.js":1075]
    this = [object Object]
2 ThreadActor.prototype._addSource(aSource = [object Source]) ["resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/script.js":1935]
    this = [object Object]
3 ThreadActor.prototype.onNewScript(aScript = [object Script]) ["resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/script.js":1882]
    this = [object Object]
4 DynamicSourceCollector.prototype.onNewScript(script = [object Script]) ["chrome://firebug/content/debugger/script/sourceTool.js":408]
    this = [object Object]

and in frame 0 there calls into mozilla::jsinspector::nsJSInspector::EnterNestedEventLoop.  This starts pumping events, and one of those events ends up being the "done loading" event for the _second_ deferred script.  Note that at this point we haven't run the first deferred script yet, because we're still in that "we have a new script" call out to Firebug.  Anyway, the "done loading" for the second script enters nsScriptLoader::ProcessPendingRequests, pops off the first thing in mDeferRequests (which is now the second deferred script, since we popped the first one off before trying to evaluate it), and runs it.  So the second deferred scirpt runs before the first.

I expect the same thing might happen with our own devtools instead of Firebug, since all Firebug is doing is calling into our devtools' onNewScript thing.

We might be able to work around this in the scriptloader, but it's hard, especially for the non-deferred-script case: in general script _execution_ is allowed to run new scripts, and from the point of view of the scriptloader compilation and execution is an atomic operation done by the JS engine.  The fact that the JS engine spins the event loop in the middle of that is ... unexpected.

Jim, Eddie do you know what the story is with the event loop spinning here?  It seems like it could generally cause out of order script execution, not just for deferred scripts, though it's simplest to trigger it using cached deferred scripts because using those minimizes the amount of raciness involved.  Eddie, you seem to have blame here per http://hg.mozilla.org/mozilla-central/rev/d9a7a06ee0b5 and I suspect this is all a regression from bug 1149115.  That would more or less match when this bug was filed: bug 1149115 shipped in Firefox 40 on 2015-08-10 and this bug was filed on 2015-10-07...

Blocks: 1149115

Component: General → DOM

Flags: needinfo?(nstoddar74)

Flags: needinfo?(jimb)

Flags: needinfo?(ejpbruel)

Flags: needinfo?(admin)

Keywords: regression

Summary: Deferred scripts run out-of-order when read from cache → Deferred scripts run out-of-order when read from cache if Firebug is installed (or devtools debugger enabled, probably)

Comment 19

•

8 years ago

I guess one thing we could try doing is for the request queues in the scriptloader that are fundamentally async we could ensure that we don't process things from them while running a script.  That would at least help with deferred scripts; not sure about the others.

Though come to think of it, we run into this issue with a deferred script doing a sync XHR too.  Testcase:

  <script defer src="data:application/javascript,var%20x%20=%200;%20var%20xhr%20=%20new%20XMLHttpRequest();%20xhr.open('GET',%20'data:text/plain,aaa',%20false);%20xhr.send();%20x=1"></script>
  <script defer src="data:application/javascript,console.log(x);"></script>

This logs 0, when it should presumably log 1...

Comment 20

•

8 years ago

Indeed it does happen with our own devtools; this is the same as bug 1219229. We ameliorated the problem there by only spinning the nested event loop if there were breakpoints set; see bug 1219229 comment 33.

If someone has a breakpoint set in a script that has a source map, we need to retrieve the source map in order to set breakpoints correctly, and we must have the breakpoints set before the script begins execution. Fetching a source map is an XHR. The nested event loop is waiting for the source map request to complete.

This nested event loop causes us a lot of trouble, in exactly the way you anticipate.

We can learn that a script has a source map in two ways: the HTTP response to the request for the script can include a header; or the script itself may contain a specially-formatted comment. Either one provides the URL of the source map.

I think fixing this will inevitably require changes to the script loader.

One possibility: treat the script as not ready to run until the script and its source map have both been fetched --- that is, we would integrate source map retrieval into the script loader. The Debugger could state up front that it's interested in source maps, and SpiderMonkey could have a function to tell Gecko whether a given compartment cared; so we'd only need to bother fetching a source map if someone wanted it. However, you say, "from the point of view of the script loader, compilation and execution is an atomic operation done by the JS engine"; the loader couldn't know if a source map needs to be loaded until after compilation finishes. So it'd have to break that atomic operation up into two phases.

(I'm kind of surprised it treats them as atomic; are you sure that's right? I was sure it used off-main-thread JS compilation, which I'm pretty sure uses the event loop to kick off execution when the compilation is complete.)

Second possibility: (I'm not familiar with this code, so look out for any bad inferences I've made!) Let mDeferRequests have a new state for each script, IsRunning. Once a script IsReadyToRun, we mark it IsRunning and begin its execution, leaving it at the head of the queue. When the head of the queue IsRunning, ProcessPendingRequests returns, leaving the front entry in the queue. Only once execution completes would we dequeue the script.

This would mean that any re-entrant calls to ProcessPendingResults while the script executes would not kick off execution of new scripts, unless they were pushed onto the front of the queue. I don't know if that happens.

Comment 21

•

8 years ago

(In reply to Boris Zbarsky [:bz] from comment #19)
> I guess one thing we could try doing is for the request queues in the
> scriptloader that are fundamentally async we could ensure that we don't
> process things from them while running a script.  That would at least help
> with deferred scripts; not sure about the others.
> 
> Though come to think of it, we run into this issue with a deferred script
> doing a sync XHR too.  Testcase:
> 
>   <script defer
> src="data:application/javascript,var%20x%20=%200;
> %20var%20xhr%20=%20new%20XMLHttpRequest();%20xhr.open('GET',%20'data:text/
> plain,aaa',%20false);%20xhr.send();%20x=1"></script>
>   <script defer src="data:application/javascript,console.log(x);"></script>
> 
> This logs 0, when it should presumably log 1...

Would the "IsRunning" state I suggested above fix this too?

Flags: needinfo?(jimb)

Comment 22

•

8 years ago

> We ameliorated the problem there by only spinning the nested event loop if there were breakpoints set

Ah.  I wonder whether Firebug always sets breakpoints or something... I vaguely recall something like that.

> If someone has a breakpoint set in a script that has a source map

Can an inline script have a source map?  Seems to me like it can, with specially-formatted comment thing; more on this below.

> I think fixing this will inevitably require changes to the script loader.

I think it's impossible to fix in the script loader for the inline script case...

> One possibility: treat the script as not ready to run until the script and its source map have both been
> fetched

For non-inline scripts, this seems like a sane thing to do, I agree.

> So it'd have to break that atomic operation up into two phases.

That's not a problem in general, as long as the right APIs exist on the spidermonkey side.  Again, for non-inline scripts.

> I was sure it used off-main-thread JS compilation

That's only used in a very limited set of cases.  But yes, some of the basic infrastructure, for non-inline scripts, of asking SpiderMonkey to do something and then later running the script once the something is done is indeed in place and could be reused.

> Let mDeferRequests have a new state for each script

This is basically what comment 19 is about.  It would help with cases of event loop spinning that have nothing to do with source maps, but is a lot more fragile/complicated in general; it would take a good bit of thought.  We'd need this for cases other than defer requests, I suspect.

The complication here is that inline scripts inserted from script are expected to execute _synchronously_, before the appendChild() call returns.  On the scriptloader end that means that we have to be a bit careful in terms of which things we block on the "is running" flag if we take that approach.  On the general sourcemap fetching end, that means we just lose if an inline script has a sourcemap and breakpoint, yes?

Maybe we should just ignore the inline script problem and try to fix the general "script spins event loop" thing in the scriptloader, treating sourcemap fetches as a special case of "script spins event loop".... though conceptually, it sure would be nice to avoid the sync spin when we can and just not treat the script as ready until the sourcemap is downloaded.

Flags: needinfo?(jimb)

Comment 23

•

8 years ago

(In reply to Boris Zbarsky [:bz] from comment #22)
> The complication here is that inline scripts inserted from script are
> expected to execute _synchronously_, before the appendChild() call returns. 
> On the scriptloader end that means that we have to be a bit careful in terms
> of which things we block on the "is running" flag if we take that approach. 
> On the general sourcemap fetching end, that means we just lose if an inline
> script has a sourcemap and breakpoint, yes?

Do inline scripts go onto the mDeferRequests queue? If so, they must go on the front, because they certainly don't wait for any other loaded scripts to finish first. So they'd be dispatched just fine: they'd be sitting at the front of the queue marked as running until they completed, so any nested event loops wouldn't cause anything new to be dispatched from that queue.

If inline scripts don't go on the mDeferRequests queue, and one has a sourcemapped breakpoint, then the devtools server will spin an event loop waiting for the source map, and the only thing that would prevent nsScriptLoader::ProcessPendingRequests from running more scripts would be that the server always calls preNest, here, before processing events: 

https://hg.mozilla.org/mozilla-central/file/06678484909c/devtools/server/actors/webbrowser.js#l1622

In that sense, it's no different from being paused at a previously set breakpoint, and the debugger UI spinning the event loop for interaction with the user.

So I think I'm not understanding the problem.

Flags: needinfo?(jimb) → needinfo?(bzbarsky)

Comment 24

•

8 years ago

> Do inline scripts go onto the mDeferRequests queue? 

No, not at all.  The only things that go there are deferred scripts.  Inline scripts generally don't go into any of the scriptloader queues at all.  The cases that are interesting with inline scripts are the following:

1)  Inline script inserted directly into the DOM.  This will basically call directly into ProcessRequest via a scriptrunner.  The problem is what happens if _two_ scripts are inserted in a single call (e.g. an appendChild of a DocumentFragment).  Per spec, those scripts are expected to run, in order, before the call returns.  We'll have scriptrunner runnables for them both; if we start spinning the event loop for the first one, I'm not sure whether the second one will end up running before the first or not.

2)  Inline script inserted via document.write.  This calls directly into ProcessRequest without using scriptrunners, so I guess this is ok.

> and the only thing that would prevent nsScriptLoader::ProcessPendingRequests from running more scripts
> would be that the server always calls preNest, here

Yeah, afaict neither windowUtils.suppressEventHandling nor windowUtils.suspendTimeouts suspend the scriptloader.  Maybe they should... Olli, thoughts?  That would also address the sync XHR thing...

> So I think I'm not understanding the problem.

The fundamental problem is that the spec requirements around this stuff are complicated, and the resulting code is complicated and fragile, and hard to reason about even without introducing nested event loop spinning... ;)

Basically, I view whatever we do in the scriptloader here as a workaround at best.  It might be a necessary workaround, but I think that in addition to that we should make sourcemap fetches part of the "is this script ready to run?" process for non-inline scripts at least.  For inline scripts, there's really not much we can do short of blocking the world to fetch the sourcemap.  :(

Flags: needinfo?(bzbarsky) → needinfo?(bugs)

Comment 25

•

8 years ago

The preNest function I linked to in comment 23 ought to do something that prevents the event loop from running any further queued content scripts, via nsScriptLoader::ProcessPendingRequests or otherwise, until the postNest function (just below it) is called to balance it out.

The "IsRunning" state I proposed might help with synchronous XHR and "delay" scripts, which doesn't involve the debugger at all. But it sounds like it certainly won't handle all the cases.

For example, if we insert an out-of-line script, Gecko will start fetching it. If we then hit a breakpoint, the server will spin an event loop. If the out-of-line script finishes being loaded, then if I understand correctly, there's presently nothing in nsScriptLoader::ProcessPendingRequests that would prevent it from running the script, even though we're supposed to be stopped at a breakpoint in another content script.

Updated

•

8 years ago

Flags: needinfo?(ejpbruel)

Comment 26

•

8 years ago

(In reply to Boris Zbarsky [:bz] from comment #24)
> Basically, I view whatever we do in the scriptloader here as a workaround at
> best.  It might be a necessary workaround, but I think that in addition to
> that we should make sourcemap fetches part of the "is this script ready to
> run?" process for non-inline scripts at least.  For inline scripts, there's
> really not much we can do short of blocking the world to fetch the
> sourcemap.  :(

This worries me a bit, because in many ways pausing at a breakpoint is a similar situation. We need to spin the event loop to allow the debugger UI to be live, and to allow other tabs to be live. The whole debugger design --- required by Firefox's design, mind you --- is built on the assumption that we can pause the debuggee while still processing events in other parts of the browser.

Comment 27

•

8 years ago

> then if I understand correctly, there's presently nothing in nsScriptLoader::ProcessPendingRequests that
> would prevent it from running the script

I believe right now that is correct.  It's really sounding like we should add something that would make this case work, and that would solve the other problems as well, at least in the common cases.

I understand why the debugger is doing what it is and why it needs to do it.  It's unfortunate that the assumption it needs to make is not actually strictly true at the moment, until we sort out our event queue story, but that's not the debugger's fault, obviously.

Comment 28

•

8 years ago

Oh, and the reason I still think we should do the sourcemap fetches before we decide the script is ready to run: if nothing else, that would allow us to parallelize those fetches, if we do it right, instead of serializing them like we do now.

Comment 29

•

8 years ago

Note to self: Just doing AddExecuteBlocker() on the scriptloader as needed does NOT work, because execute blockers only affect parser-blocking and XSLT scripts, not all the other kinds of scripts.

Comment 30

•

8 years ago

I expect my patch in bug 1267989 will fix this by making suppressEventHandling() also block all script execution.  I would have just put it here, but I can't reproduce the firebug+defer issue today, so can't verify that it does in fact get fixed....

Depends on: 1267989

Flags: needinfo?(bugs)

Comment 31

•

8 years ago

If people get a chance to retest in tomorrow's nightly, that would be very much appreciated!

Michelle Funches - QA

Comment 32

•

8 years ago

Looks Good: I referenced original description of error, Comment 7 and Comment 10.
Version 	49.0a1
Build ID 	20160527030220
User Agent 	Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:49.0) Gecko/20100101 Firefox/49.0

Milan

Comment 33

•

8 years ago

I believe I ran into the sync XHR case described in the comment: https://bugzilla.mozilla.org/show_bug.cgi?id=1212696#c19

We recently introduced deferred loading to improve first paint time. The scripts load in a fashion similar to the following:

<script defer src="jquery.js"></script>
<script defer src="jquery.i18.properties.js"></script>
<script defer src="support_file_that_invokes_jquery_i18n_and_creates_helper_functions.js"></script>
<script defer src="file_uses_helper_functions.1.js"></script>
<script defer src="file_uses_helper_functions.2.js"></script>
<script defer src="file_uses_helper_functions.n.js"></script>

The jquery i18n properties library performs some synchronous XHR requests when it is invoked in the support file.

With Firefox 48.0b1 I observed what looks like incorrect defer load order. The files that use the helper function cause errors when run stating that the helper functions are not available. Environment information: no extensions and all plugins set to ask or disabled, developer tools not opened during page load but instead opened several seconds later to check console messages.

With Firefox Nightly 50.0a1 (2016-06-20) defer load order seems to work correctly (as in no console errors) but I have not tried any rigorous verification of the sync xhr.

Firefox Developer Edition 49.0a2 (2016-06-20) defer load order also appears to work correctly.

It was mentioned in https://bugzilla.mozilla.org/show_bug.cgi?id=1212696#c18 that the issue may have been introduced in Firefox 40. I tested Firefox 39.03 and Firefox 36 but both show the incorrect defer loading behavior, so it is possible the incorrect behavior has been around longer. Older browsers retrieved from here: https://ftp.mozilla.org/pub/firefox/releases/

For any jquery.18n.properties users who happen to run into this behavior I filed an issue on github: https://github.com/jquery-i18n-properties/jquery-i18n-properties/issues/43

If I disable the plugin and thereby prevent the Synchronous XHR then all the tested browsers appear to respect the defer load order (at least as far as I can tell superficially). I have not tested if configuring the plugin to perform Asynchronous XHR while the deferred scripts are running would still cause any problems in older releases.

To summarize the changes in nightly look good to me when mixing defer and sync xhr, but I have not tested if any issue shows up for defer and async xhr.