1222690 - Communication between add-on script and content script at start no longer working

Status: RESOLVED FIXED

(Add-on SDK Graveyard :: General, defect)

Description

[u529383]

Attachment: Add-on test.xpi

As of Nightly 45.0a1 (2015-11-05) and 45.0a1 (2015-11-06) included (thanks to Aryx over at irc#developers for confirming this) the content script self.port.on is no longer getting called when the content script runs, instead it is only called after the page is complete (readyState = complete).

Attached follows a simple test add-on which posts to the browser console the current document readyState in two different stages:

2 = content script ran
3 = self.port.on was called

The following is the current behavior in Firefox 42 stable:

test:1 Content script is attached, emiting to port
test:2 content script finished running, document.readyState is: loading
test:3 self.port.on received, document.readyState is: loading

The following is the current behavior in at least the two latest Nightlies:

test:1 Content script is attached, emiting to port
2 content script finished running, document.readyState is: loading
3 self.port.on received, document.readyState is: complete

Stage 3 in Nightlies confirms that the port communication is only happening when the page load is complete and ready.

This problem is breaking any add-on that depends on the self.port on to be called at the same early stages.

Remember to enable console log in the about:config page for the browser console to receive the logs.
Set extensions.sdk.console.logLevel string all

Comment 1

[u529383]

Further testing reveals that the same problem is also present in port.postMessage api, so any form of add-on script -> content script communication is not happening until the page readystate = complete.

To further aggravate this problem, if the page in which the content script is attached to there is any element (image, iframe, script) that takes a long time to load, the add-on/content script communications wait until those elements are finished loading.

The issue might be related to promises and them working too late when they shouldn't. Every add-on depending on these types of communications during page loading stages will break if this isn't corrected.

Comment 2

[ngyikp]

Also having this same issue, the content script on my extension needs to postMessage back to the background page in order to load user settings as soon as possible, and on Nightly, my extension feels like it's lagging and only returns the settings when the page is nearly done.

This line on this commit back from Oct 17 seems suspect: https://github.com/mozilla/addon-sdk/commit/dd98f67bb20ef334133f8d031b366b862c939e28#diff-8376473758ee81f3de6f8a575358e017R56

Comment 3

[ngyikp]

This regression has gone all the way to Firefox 45 stable and now my users are starting to complain/wonder why it seems slower to launch than usual.

Comment 5

[Loic]

Please, set tracking flags when the regression is recent.

Comment 6

[Luca Greco [:rpl] [:luca] [:lgreco]]

Attachment: Bug 1222690 - SDK Content Script should not be frozen during the page loading.

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

Comment 7

[Luca Greco [:rpl] [:luca] [:lgreco]]

Attachment: Bug 1222690 - Test SDK Content Scripts are not frozen before document.readyState complete.

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

Comment 8

[Luca Greco [:rpl] [:luca] [:lgreco]]

Comment on attachment 8761224 [details]
Bug 1222690 - SDK Content Script should not be frozen during the page loading.

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

Comment 9

[Luca Greco [:rpl] [:luca] [:lgreco]]

Comment on attachment 8761225 [details]
Bug 1222690 - Test SDK Content Scripts are not frozen before document.readyState complete.

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

Comment 10

[Luca Greco [:rpl] [:luca] [:lgreco]]

https://reviewboard.mozilla.org/r/58514/#review55392

::: addon-sdk/source/lib/sdk/content/worker-child.js:54
(Diff revision 2)
> -    // If the document is still loading wait for it to finish before passing on
> +    // If the document is still initializing wait for it to finish before passing on
>      // received messages
> -    this.frozen = this.window.document.readyState == "loading";
> +    this.frozen = this.window.document.readyState == "uninitialized";
>      this.frozenMessages = [];

It looks like the issue is related to this line.

If the worker-child is frozen is not set to true on readyState == "loading" (and in this patch I opted to set it frozen only if the readyState is "uninitialized"), the content script is able to receive and send the messages during the page loading (e.g. readyState is still loading or interactive), as it was before the change related to e10s applied to this SDK module.

I've put together a test addon to reproduce the above issue and be sure that once this change is applied the content scripts are working as expected (and so that we can keep an eye on it for similar regressions in the future).

The test case is in a separate patch in this mozreview queue (mainly because I was unable to find a better way to provide a mock server for the test addon besides including a new copy of the httpd module like the other content-script test addons do, and I wanted to keep this patch minimal so that it is easier to read)

Comment 11

[Luca Greco [:rpl] [:luca] [:lgreco]]

Pushed to try (so that we can check that the change doesn't affect the other tests in the jetpack test suite):

https://treeherder.mozilla.org/#/jobs?repo=try&revision=9b22f9ef9ca5

Comment 12

[Gabor Krizsanits (INACTIVE)]

Comment on attachment 8761224 [details]
Bug 1222690 - SDK Content Script should not be frozen during the page loading.

https://reviewboard.mozilla.org/r/58514/#review56694

::: addon-sdk/source/lib/sdk/content/worker-child.js:56
(Diff revision 2)
>  
>      this.sandbox = WorkerSandbox(this, this.window);
>  
> -    // If the document is still loading wait for it to finish before passing on
> +    // If the document is still initializing wait for it to finish before passing on
>      // received messages
> -    this.frozen = this.window.document.readyState == "loading";
> +    this.frozen = this.window.document.readyState == "uninitialized";

I'm not against leaving the "uninitialized" case here just in case. But since I think this should never happen and if it does it's a bug, could we log a warning to the console? I wonder if we get a bug report on that... The comment should also mention this.

Comment 13

[Luca Greco [:rpl] [:luca] [:lgreco]]

Comment on attachment 8761224 [details]
Bug 1222690 - SDK Content Script should not be frozen during the page loading.

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

Comment 14

[Luca Greco [:rpl] [:luca] [:lgreco]]

Comment on attachment 8761225 [details]
Bug 1222690 - Test SDK Content Scripts are not frozen before document.readyState complete.

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

Comment 15

[Luca Greco [:rpl] [:luca] [:lgreco]]

https://reviewboard.mozilla.org/r/58514/#review56694

> I'm not against leaving the "uninitialized" case here just in case. But since I think this should never happen and if it does it's a bug, could we log a warning to the console? I wonder if we get a bug report on that... The comment should also mention this.

How about the following updated version?

```
    // If the document has an unexpected readyState, its worker-child instance is initialized
    // as frozen until one of the known readyState is reached.
    let initialDocumentReadyState = this.window.document.readyState;
    this.frozen = [
      "loading", "interactive", "complete"
    ].includes(initialDocumentReadyState) ? false : true;

    if (this.frozen) {
      console.warn("SDK worker-child started as frozen on unexpected initial document.readyState", {
        initialDocumentReadyState, windowLocation: this.window.location.href,
      });
    }
```

(it is the same version I've just pushed to mozreview, but I'm pasting here a fragment to make the discussion easier to follow)

Comment 16

[Luca Greco [:rpl] [:luca] [:lgreco]]

pushed to try of the last version of the attached patches:

- https://treeherder.mozilla.org/#/jobs?repo=try&revision=e84d2c2b652d

Comment 17

[Gabor Krizsanits (INACTIVE)]

Comment on attachment 8761225 [details]
Bug 1222690 - Test SDK Content Scripts are not frozen before document.readyState complete.

https://reviewboard.mozilla.org/r/58516/#review56908

Since we already have this file copied in 3 other test add-ons I'm fine with this. I don't think it's worth your time to try and find a nicer way to include it into test add-ons if no one has done that already.

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/fx-team/rev/311d8b26687a
SDK Content Script should not be frozen during the page loading. r=gabor
https://hg.mozilla.org/integration/fx-team/rev/6cb5178d51b3
Test SDK Content Scripts are not frozen before document.readyState complete. r=gabor

Comment 19

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/311d8b26687a
https://hg.mozilla.org/mozilla-central/rev/6cb5178d51b3

Comment 20

[Sylvestre Ledru [:Sylvestre]]

Luca, are you going to ask for an uplift in 48 and/or 49?

Comment 21

[Luca Greco [:rpl] [:luca] [:lgreco]]

Comment on attachment 8761224 [details]
Bug 1222690 - SDK Content Script should not be frozen during the page loading.

Approval Request Comment For Aurora and Beta
on the first patch (which contains the actual fix)

[Feature/regressing bug #]:
Bug 1222960

[User impact if declined]:
This issue has an impact on users with SDK-based addons that are using the PageMod or Worker classes to access and manipulate the DOM in the content windows. The content scripts will not be able to receive or sending messages until the page has been fully loaded, this regression seems to be introduced in Firefox 45 (with a rewrite of the related SDK modules, needed for e10s) and addon developers and their users are already encountering this issue (which is often reported as "addons are slower on Firefox >= 45" issues) 

[Describe test coverage new/current, TreeHerder]:
The test coverage of this SDK feature is pretty high, but it had no specific test case to cover this scenario, and these patches introduce both the fix and a new test to prevents similar regressions could happen without being noticed.

- Try build on Aurora: https://treeherder.mozilla.org/#/jobs?repo=try&revision=73ebe1cda339
- Try build on Beta:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=aeb02060141a

[Risks and why]: 
We tried to minimize the risks by keeping the actual fix small. This SDK feature had already a good test coverage (excluding the specific scenario related to this regression), and we are introducing a new SDK test addon which tests specifically the regressed scenario.

[String/UUID change made/needed]:
none

Comment 22

[Luca Greco [:rpl] [:luca] [:lgreco]]

Comment on attachment 8761225 [details]
Bug 1222690 - Test SDK Content Scripts are not frozen before document.readyState complete.

Approval Request Comment For Aurora and Beta
on the second patch (which contains the new test addon which we are introducing to prevent similar regression to happen unnoticed)

[Feature/regressing bug #]:
Bug 1222960

[User impact if declined]:
This issue has an impact on users with SDK-based addons that are using the PageMod or Worker classes to access and manipulate the DOM in the content windows. The content scripts will not be able to receive or sending messages until the page has been fully loaded, this regression seems to be introduced in Firefox 45 (with a rewrite of the related SDK modules, needed for e10s) and addon developers and their users are already encountering this issue (which is often reported as "addons are slower on Firefox >= 45" issues) 

[Describe test coverage new/current, TreeHerder]:
The test coverage of this SDK feature is pretty high, but it had no specific test case to cover this scenario, and these patches introduce both the fix and a new test to prevents similar regressions could happen without being noticed.

- Try build on Aurora: https://treeherder.mozilla.org/#/jobs?repo=try&revision=73ebe1cda339
- Try build on Beta:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=aeb02060141a

[Risks and why]: 
We tried to minimize the risks by keeping the actual fix small. This SDK feature had already a good test coverage (excluding the specific scenario related to this regression), and we are introducing a new SDK test addon which tests specifically the regressed scenario.

[String/UUID change made/needed]:
none

Comment 23

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8761224 [details]
Bug 1222690 - SDK Content Script should not be frozen during the page loading.

ok, let's do it!

Comment 24

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8761225 [details]
Bug 1222690 - Test SDK Content Scripts are not frozen before document.readyState complete.

should be in 48 beta 3

Comment 25

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-beta/rev/47fda6d9fe0c
https://hg.mozilla.org/releases/mozilla-beta/rev/79501c3f69ce

Comment 26

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/9be81aef870a
https://hg.mozilla.org/releases/mozilla-aurora/rev/d09ce0726c25