If you think a bug might affect users in the 57 release, please set the correct tracking and status flags for Release Management.

Order of execution of content scripts in Firefox52 is not correct

RESOLVED FIXED in Firefox -esr52

Status

()

Toolkit
WebExtensions: General
P1
normal
RESOLVED FIXED
6 months ago
6 months ago

People

(Reporter: sachinjain024, Assigned: zombie)

Tracking

52 Branch
mozilla55
Points:
---
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox52 wontfix, firefox-esr52 fixed, firefox53 fixed, firefox54 fixed, firefox55 fixed)

Details

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(3 attachments)

(Reporter)

Description

6 months ago
Created attachment 8847771 [details]
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
(Assignee)

Comment 1

6 months ago
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
(Assignee)

Updated

6 months ago
Flags: needinfo?(sachinjain024)
(Assignee)

Comment 2

6 months ago
Can confirm this.  It is a regression, so I'm guessing P1.
Assignee: nobody → tomica
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
Flags: needinfo?(sachinjain024)
Priority: -- → P1
Comment hidden (mozreview-request)
(Assignee)

Updated

6 months ago
Attachment #8848125 - Flags: review?(kmaglione+bmo)
(Assignee)

Comment 4

6 months ago
mozreview-review
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 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.
Attachment #8848125 - Flags: review?(kmaglione+bmo)
Comment hidden (mozreview-request)
(Assignee)

Comment 7

6 months ago
mozreview-review
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

6 months ago
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).
(Assignee)

Comment 9

6 months ago
(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 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`
Attachment #8848125 - Flags: review?(kmaglione+bmo) → review+
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 hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Updated

6 months ago
Attachment #8848740 - Flags: review?(kmaglione+bmo)
(Assignee)

Comment 14

6 months ago
> 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
(Assignee)

Comment 15

6 months ago
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
Attachment #8848125 - Flags: approval-mozilla-beta?
Attachment #8848125 - Flags: approval-mozilla-aurora?
Comment on attachment 8848740 [details]
Bug 1347700 - Test async loading of content scripts

https://reviewboard.mozilla.org/r/121642/#review123680
Attachment #8848740 - Flags: review?(kmaglione+bmo) → review+
(Assignee)

Updated

6 months ago
Attachment #8848740 - Flags: checkin?

Comment 17

6 months ago
Pushed by archaeopteryx@coole-files.de:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2a9f685bbf0c
Test async loading of content scripts. r=kmag
(Assignee)

Updated

6 months ago
Attachment #8848740 - Flags: checkin? → checkin+

Comment 18

6 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/2a9f685bbf0c
Status: ASSIGNED → RESOLVED
Last Resolved: 6 months ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55

Updated

6 months ago
status-firefox53: --- → affected
status-firefox54: --- → affected
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+.
Attachment #8848125 - Flags: approval-mozilla-beta?
Attachment #8848125 - Flags: approval-mozilla-beta+
Attachment #8848125 - Flags: approval-mozilla-aurora?
Attachment #8848125 - Flags: approval-mozilla-aurora+
Since bug 1333990 now landed, can this also land on m-c ?
Flags: needinfo?(tomica)
(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
(Assignee)

Comment 22

6 months ago
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).
Flags: needinfo?(tomica)
status-firefox52: --- → affected
status-firefox-esr52: --- → affected

Comment 23

6 months ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-aurora/rev/9fb6d7fae014
https://hg.mozilla.org/releases/mozilla-aurora/rev/38366a1d4230
status-firefox54: affected → fixed

Comment 24

6 months ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-beta/rev/65274868fd89
https://hg.mozilla.org/releases/mozilla-beta/rev/87a4ac4ccadc
status-firefox53: affected → fixed
Wontfix for 52.  Should this be considered for esr52?
status-firefox52: affected → wontfix
(Assignee)

Comment 26

6 months ago
(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.
(Assignee)

Comment 27

6 months ago
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
Attachment #8848125 - Flags: approval-mozilla-esr52?
(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 on attachment 8848125 [details]
Bug 1347700 - Fix async loading of content scripts

webextensions script loading fix, esr52+
Attachment #8848125 - Flags: approval-mozilla-esr52? → approval-mozilla-esr52+

Comment 30

6 months ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-esr52/rev/ee706896916c
https://hg.mozilla.org/releases/mozilla-esr52/rev/08ecc2d92f81
status-firefox-esr52: affected → fixed
Flags: in-testsuite+
You need to log in before you can comment on or make changes to this bug.