1347700 - Order of execution of content scripts in Firefox52 is not correct

Status: RESOLVED FIXED

(WebExtensions :: General, defect, P1)

Description

[sachinjain024]

Attachment: Screenshot 2017-03-13 21.27.24.png

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3041.0 Safari/537.36

Steps to reproduce:

I have a Chrome+Mozilla web extension, Requestly. I load two content scripts for a particular page with the following declaration in manifest

"content_scripts": [
    {
      "matches": [ "*://requestly.in/rules/*" ],
      "css": [ "generated/pages/css/main.css" ],
      "js": [ "generated/pages/js/libs.js", "generated/pages/js/main.js" ]
    }
  ],

With this declaration, I assumed main.js should be executed after libs.js is executed because main.js is dependent on libs.js

libs.js contain libraries
main.js contain app specific code

I put console logs at the beginning and end of both the scripts to ensure the order of execution and I found a strange behavior.


Actual results:

Order of execution of these content scripts is not as per documentation (https://developer.mozilla.org/en-US/Add-ons/WebExtensions/manifest.json/content_scripts) 

Here are the result of console logs I put at the beginning and end of the file
1. main.js load start
2. libs.js load started
3. libs.js load end

--Error-- I did not receive "main.js load end" log because I got error in main.js. Main.js contains app specific code which depends on libs.js


Expected results:

Content scripts should be loaded in order as they are specified in manifest.json

Comment 1

[Tomislav Jovanovic :zombie]

Hm, it looks like a bit of aggressive optimization from [1] made loading the scripts async, but didn't wait for first script to resolve before loading the next one..

Sachinjain can you please attach the full extension source that exhibits the problem?  I'm going to try to replicate on my own, but if my assumption is correct, hitting the right race condition might be tricky.

1) http://searchfox.org/mozilla-central/source/toolkit/components/extensions/ExtensionContent.jsm#269-271

Comment 2

[Tomislav Jovanovic :zombie]

Can confirm this.  It is a regression, so I'm guessing P1.

Comment 3

[Tomislav Jovanovic :zombie]

Attachment: Bug 1347700 - Fix async loading of content scripts

Review commit: https://reviewboard.mozilla.org/r/121100/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/121100/

Comment 4

[Tomislav Jovanovic :zombie]

Comment on attachment 8848125 [details]
Bug 1347700 - Fix async loading of content scripts

https://reviewboard.mozilla.org/r/121100/#review123028

::: toolkit/components/extensions/ExtensionContent.jsm:274
(Diff revision 1)
>            // Inject asynchronously unless we're expected to inject before any
>            // page scripts have run, and we haven't already missed that boat.
>            async: this.run_at !== "document_start" || when !== "document_start",
>          };
>          try {
> -          result = Services.scriptloader.loadSubScriptWithOptions(url, options);
> +          result = await Services.scriptloader.loadSubScriptWithOptions(url, options);

We could be more fancy here, and not `await` on last (or only) script, but I expect doesn't matter much.

Comment 5

[Kris Maglione [:kmag]]

Comment on attachment 8848125 [details]
Bug 1347700 - Fix async loading of content scripts

https://reviewboard.mozilla.org/r/121100/#review123102

::: toolkit/components/extensions/ExtensionContent.jsm:274
(Diff revision 1)
>            // Inject asynchronously unless we're expected to inject before any
>            // page scripts have run, and we haven't already missed that boat.
>            async: this.run_at !== "document_start" || when !== "document_start",
>          };
>          try {
> -          result = Services.scriptloader.loadSubScriptWithOptions(url, options);
> +          result = await Services.scriptloader.loadSubScriptWithOptions(url, options);

This is going to caue problems if the script evaluates to a promise. Let's just use sync loading for all but the last script for now. Bug 1333990 will fix the issues with async loading.

::: toolkit/components/extensions/test/mochitest/test_ext_contentscript_async_loading.html:24
(Diff revision 1)
> +        // Use sync XHR to delay.
> +        const sync = new XMLHttpRequest();
> +        sync.open("GET", "https://example.org/", false);
> +        sync.send();

I'd rather we not make any guarantees about the order of execution in this case. If you spin the event loop, all bets are off.

Comment 6

[Tomislav Jovanovic :zombie]

Comment on attachment 8848125 [details]
Bug 1347700 - Fix async loading of content scripts

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121100/diff/1-2/

Comment 7

[Tomislav Jovanovic :zombie]

Comment on attachment 8848125 [details]
Bug 1347700 - Fix async loading of content scripts

https://reviewboard.mozilla.org/r/121100/#review123164

::: toolkit/components/extensions/test/mochitest/test_ext_contentscript_async_loading.html:25
(Diff revision 2)
> +        this.count = 0;
> +        ${adder.repeat(50000)};  // 2Mb
> +        browser.test.assertEq(this.count, 50000, "A 50k line script");

Figured out something that's not too bad, and seems to reliably fail without the patch.

Comment 8

[Anton]

I faced the same problem with content_scripts. I try to inject 2 files ["commons.js", "content.js"] but content.js always performs fist. 
I made a test by injecting 2 empty files with simple console.log and they were executed in the order they appeared in the array. But then I appended 700Kb of random js code to one of them and now this file is always executed last.
It seems like order of injecting depends on file size, (in my case commons.js file 2 times bigger then content.js).

Comment 9

[Tomislav Jovanovic :zombie]

(In reply to Anton from comment #8)
> But then I appended 700Kb of random js code to one of them
> and now this file is always executed last.

Independent confirmation, great! 

My tests also showed problems start at 700kb, so now I feel better about the test above.

Comment 10

[Kris Maglione [:kmag]]

Comment on attachment 8848125 [details]
Bug 1347700 - Fix async loading of content scripts

https://reviewboard.mozilla.org/r/121100/#review123628

Thanks! r=me, but, sorry, this is going to have to land directly to aurora. I didn't think about the conflicts before landing bug 1333990.

Can you do a try run rebased onto Aurora and request uplift to Aurora and beta, please?

::: toolkit/components/extensions/ExtensionContent.jsm:263
(Diff revision 2)
>      }
>  
>      let result;
>      let scheduled = this.run_at || "document_idle";
>      if (shouldRun(scheduled)) {
> -      for (let url of this.js) {
> +      for (let i = 0; i < this.js.length; i++) {

`for (let [i, url] of this.js.entries())`

::: toolkit/components/extensions/ExtensionContent.jsm:264
(Diff revision 2)
>  
>      let result;
>      let scheduled = this.run_at || "document_idle";
>      if (shouldRun(scheduled)) {
> -      for (let url of this.js) {
> -        url = this.extension.baseURI.resolve(url);
> +      for (let i = 0; i < this.js.length; i++) {
> +        let url = this.extension.baseURI.resolve(this.js[i]);

No need for the `baseURI.resolve`

Comment 11

[Kris Maglione [:kmag]]

Comment on attachment 8848125 [details]
Bug 1347700 - Fix async loading of content scripts

https://reviewboard.mozilla.org/r/121100/#review123628

Oh, but the tests should still land on central, of course.

Comment 12

[Tomislav Jovanovic :zombie]

Attachment: Bug 1347700 - Test async loading of content scripts

Review commit: https://reviewboard.mozilla.org/r/121642/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/121642/

Comment 13

[Tomislav Jovanovic :zombie]

Comment on attachment 8848125 [details]
Bug 1347700 - Fix async loading of content scripts

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/121100/diff/2-3/

Comment 14

[Tomislav Jovanovic :zombie]

> Can you do a try run rebased onto Aurora and request uplift

https://treeherder.mozilla.org/#/jobs?repo=try&revision=561dbf0a89371be4a6b1b04000897a4d518f57b6


> Oh, but the tests should still land on central, of course.

Test separated out r? https://reviewboard.mozilla.org/r/121642/diff

Comment 15

[Tomislav Jovanovic :zombie]

Comment on attachment 8848125 [details]
Bug 1347700 - Fix async loading of content scripts

Approval Request Comment
> [Feature/Bug causing the regression]:
Optimization from Bug 1312690 started loading content scripts asynchronously.

> [User impact if declined]:
A large number of extensions that use libraries in content scripts are potentially broken.

> [Is this code covered by automated tests?]:
Yes, good coverage of content scripts, and additional test for this regression. 

> [Has the fix been verified in Nightly?]:
Didn't land because of conflicts with bug 1333990 (comment 10), but verified manually and on try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=3fb083a9ecf3

> [Needs manual test from QE? If yes, steps to reproduce]: 
I don't believe it does (Though I don't know the criteria for this).

> [List of other uplifts needed for the feature/fix]:
The tests were separated into the other attachment:
https://reviewboard.mozilla.org/r/121642/diff

> [Is the change risky?]:
No

> [Why is the change risky/not risky?]:
This patch (mostly) reverts to the correct behavior from before bug 1312690 landed. 

> [String changes made/needed]:
N/A

Comment 16

[Kris Maglione [:kmag]]

Comment on attachment 8848740 [details]
Bug 1347700 - Test async loading of content scripts

https://reviewboard.mozilla.org/r/121642/#review123680

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2a9f685bbf0c
Test async loading of content scripts. r=kmag

Comment 18

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/2a9f685bbf0c

Comment 19

[Gerry Chang [:gchang]]

Comment on attachment 8848125 [details]
Bug 1347700 - Fix async loading of content scripts

Fix an incorrect order of execution of content scripts and also include tests. Aurora54+ & Beta53+.

Comment 20

[Carsten Book [:Tomcat]]

Since bug 1333990 now landed, can this also land on m-c ?

Comment 21

[Carsten Book [:Tomcat]]

(In reply to Carsten Book [:Tomcat] from comment #20)
> Since bug 1333990 now landed, can this also land on m-c ?

err pressed enter too soon, i mean the Fix async loading of content scripts

Comment 22

[Tomislav Jovanovic :zombie]

No, bug 1333990 incidentally fixed this same issue, but is too complex/untested to get uplifted to aurora/beta.  And since this is a regression, we need to uplift a simpler fix, which is this bug.

(Tests landed on m-c, confirm this).

Comment 23

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/9fb6d7fae014
https://hg.mozilla.org/releases/mozilla-aurora/rev/38366a1d4230

Comment 24

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-beta/rev/65274868fd89
https://hg.mozilla.org/releases/mozilla-beta/rev/87a4ac4ccadc

Comment 25

[Julien Cristau [:jcristau]]

Wontfix for 52.  Should this be considered for esr52?

Comment 26

[Tomislav Jovanovic :zombie]

(In reply to Julien Cristau [:jcristau] from comment #25)
> Wontfix for 52.  
Can you please give the reason behind this decision?  Is there no point release planned/expected, or is this considered not important enough/too risky?

> Should this be considered for esr52?
Yes, I believe so, this is a significant regression, potentially impacting a large number of users, with a fairly low-risk fix.

Comment 27

[Tomislav Jovanovic :zombie]

Comment on attachment 8848125 [details]
Bug 1347700 - Fix async loading of content scripts

[Approval Request Comment]
> If this is not a sec:{high,crit} bug, please state case for ESR consideration:
Regression in Firefox 52.  Considering plans for WebExtension-only Firefox are right in the middle of this ESR, a year+ of this being broken is too long IMO.

> User impact if declined: 
A potentially large number of extensions broken.

> Fix Landed on Version:
Another fix landed in Nightly 55, this simpler (less risky) fix landed in Aurora 54.

> Risk to taking this patch (and alternatives if risky): 
Low risk, due to this fix mostly reverting to the previous code, and good test coverage.

> String or UUID changes made by this patch: 
N/A

Comment 28

[Julien Cristau [:jcristau]]

(In reply to Tomislav Jovanovic :zombie from comment #26)
> (In reply to Julien Cristau [:jcristau] from comment #25)
> > Wontfix for 52.  
> Can you please give the reason behind this decision?  Is there no point
> release planned/expected, or is this considered not important enough/too
> risky?
> 
It's not clear to me how much this breaks, it was apparently never reported on beta, and the fix landed very recently so it hasn't had any testing on beta, so I'm a bit uneasy with landing it on release directly.

Comment 29

[Julien Cristau [:jcristau]]

Comment on attachment 8848125 [details]
Bug 1347700 - Fix async loading of content scripts

webextensions script loading fix, esr52+

Comment 30

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-esr52/rev/ee706896916c
https://hg.mozilla.org/releases/mozilla-esr52/rev/08ecc2d92f81