Closed Bug 1356273 Opened 3 years ago Closed 3 years ago

document.open()/document.write() execute some content scripts twice in the same sandbox

Categories

(WebExtensions :: General, defect, major)

Unspecified
All
defect
Not set
major

Tracking

(firefox57 verified)

VERIFIED FIXED
mozilla57
Tracking Status
firefox57 --- verified

People

(Reporter: petcuandrei, Assigned: kmag)

Details

Attachments

(3 files, 1 obsolete file)

Attached image print_screen.png
User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:54.0) Gecko/20100101 Firefox/54.0
Build ID: 20170412074707

Steps to reproduce:

Install [Privacy Badger](https://addons.mozilla.org/en-US/firefox/addon/privacy-badger17/) WebExtension

Install [Dark Mode](https://addons.mozilla.org/en-US/firefox/addon/dark-mode-webextension/) also a WebExtension

Go to Google Docs https://docs.google.com/document/d/1mc_SauQzq0ICntIGm6ANjWlkhTAL42__beqzAXBNupY/edit


Actual results:

Firefox completely freezes and show message that the page is slowing down the browser


Expected results:

No combination of WebExtensions and web sites should slow down the browser. If I disable any of the addons GDocs works fine. If I visit any other site with these two addons it works fine, it's the combination of the tree of them.

I tested on stable and nightly and both have the same issue
Status: UNCONFIRMED → NEW
Has STR: --- → yes
Ever confirmed: true
OS: Unspecified → All
Does the browser show some networking activity hanging in the bottom left for you too? Like in bug 1362821?

I can reproduce this with Dark Mode (WebExtension) as the only add-on on https://servethehome.com, but only in my main profile, not in a fresh one.
URLs that hang are usually ad-related, and therefore the issue does not come up when using an ad-blocker.

Tentatively moving to Core::Networking.
Severity: normal → major
Component: Extension Compatibility → Networking
Product: Firefox → Core
Version: 52 Branch → unspecified
Attached file http log (obsolete) —
http log pursuant to 1362821#c3. hopefully this is helpful.
Both servethehome.com and docs.google.com are using HTTP2, so I'd like to ask Nick to take a look at the http log.

Thanks.
Flags: needinfo?(hurley)
Attachment #8890465 - Attachment mime type: text/plain → application/zip
I don't see any indications of http/2 issues in the logs. That, combined with the slow script dialog appearing, and disabling one of the addons making this problem disappear make me believe this is an addon issue. I don't know (and can't figure out) the appropriate component for addon issues, but I'm going to place this in Firefox:General and trust that it will find its way to the right place.
Component: Networking → General
Flags: needinfo?(hurley)
Product: Core → Firefox
Andrew, do you have cycles to check what's going on here and either update with a more precise description of how we should fix webextensions, or move to tech evangelism :: addons and ping :jorge or :theone to ping the add-on author(s) depending on what's causing this? Thank you!
Component: General → WebExtensions: General
Flags: needinfo?(aswan)
Product: Firefox → Toolkit
Snooping in on this bug.  I just built m-c with an existing profile I use.  I installed and ran Dark Mode per comment 1 and crashed immediately (some output below).  A restart did not crash, so it could just be coincidence.  

Startup shows Dark Mode is trying to use an event page which we dont support.

I then installed privacy badger and visited the google doc, no freezing on that page.

This is on osx with webextensions.remote=false.  Same result with remote=true.

Repeated with 55.0b13, no problem.


Tried to repeat with 55.0b13 and a new profile.  First installed Privacy Badger, then Dark Mode.  This time Dark Mode opened a tab to mybrowseraddon.com (didn't happen before now) and the browser frooze.  The dialog showed this Dark Mode script as the culprit:

moz-extension://45dfbdef-3daa-…/data/content_script/inject.js:94

Which is:

var observer = new MutationObserver(function (e) {
  if (head) head.appendChild(link);
  observer.disconnect();
});



Crash output from first try:

1501280642066	addons.webextension.<unknown>	WARN	Loading extension 'null': Reading manifest: Error processing background.persistent: Event pages are not currently supported. This will run as a persistent background page.
1501280652361	addons.webextension.{5834f62d-6164-4cdd-a0a3-c00c66ec9d13}	WARN	Loading extension '{5834f62d-6164-4cdd-a0a3-c00c66ec9d13}': Reading manifest: Error processing background.persistent: Event pages are not currently supported. This will run as a persistent background page.

JavaScript error: https://z-na.amazon-adsystem.com/widgets/onejs?MarketPlace=US, line 1: TypeError: a is undefined
console.error:
undefined
Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=54.0033) Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=81.3281) [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[Child 32985] WARNING: pipe error: Broken pipe: file /Users/shanec/moz/mozilla-central/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 709
Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=81.9519) [GFX1-]: Receive IPC close with reason=AbnormalShutdown
Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=83.1872) [GFX1-]: Receive IPC close with reason=AbnormalShutdown
I don't think this is unique to google docs (though it may be much easier to see there).  I got the slow script warning even in a tab with the tab that Dark Mode opens when it is installed (http://mybrowseraddon.com/dark-mode.html?v=0.1.9&type=install)

With some very clumsy poking around I got down to this code inside the content script that Dark Mode injects into every page:
```
var head = document.documentElement || document.head || document.querySelector("head");
var link = document.getElementById("dark-mode");
if (!link) {
  link = document.createElement("link");
  link.setAttribute("type", "text/css");
  link.setAttribute("id", "dark-mode");
  link.setAttribute("rel", "stylesheet");
  if (head) head.appendChild(link);
}

// other stuff elided

var observer = new MutationObserver(function (e) {
  if (head) head.appendChild(link);
  observer.disconnect();
});

// other stuff elided

observer.observe(document, {"childList": true, "subtree": true});
```

I'm not sure why the code is written this way (the MutationObserver seems like an over-engineered alternative to DOMContentLoaded?) but for some reason the callback in the observer is being called over and over.  The callback is not throwing so it is successfully calling disconnect() which is supposed to prevent any further invocations of the callback.
The observer is set up (ie observe() is called) only in once place, from the top level of the script, so the callback is not getting re-registered.
From the content script it is hard to get much detail about a MutationObserver instance but I notice that the first time the callback is invoked, the MutationObserver passed as the second argument to the callback (not present in the code snippet above) is == to the variable `observer` in the script.  But in all the subsequent onvications, it is a different instance of MutationObserver which is mysterious, the code above is the only reference to MutationObserver in the extension.

I don't know much about MutationObserver, let's try somebody who does.  :smaug, any thoughts?
Flags: needinfo?(aswan) → needinfo?(bugs)
more with b13:  

I see a lot of this in the console when running dark mode alone:

[Exception... "Must have a non-null string spec or nsIFile object"  nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)"  location: "JS frame :: resource://gre/modules/ExtensionParent.jsm :: ProxyContextParent :: line 307"  data: no]  (unknown)
	ProxyContextParent resource://gre/modules/ExtensionParent.jsm:307:16
	ContentScriptContextParent resource://gre/modules/ExtensionParent.jsm:795:19
	createProxyContext resource://gre/modules/ExtensionParent.jsm:578:17
	receiveMessage resource://gre/modules/ExtensionParent.jsm:521:11
Error: WebExtension context not found!  ExtensionParent.jsm:695:13

Nightly only produces:

Error: WebExtension context not found!  ExtensionParent.jsm:778:13
(In reply to Andrew Swan [:aswan] from comment #7)

> From the content script it is hard to get much detail about a
> MutationObserver instance but I notice that the first time the callback is
> invoked, the MutationObserver passed as the second argument to the callback
> (not present in the code snippet above) is == to the variable `observer` in
> the script.  But in all the subsequent onvications, it is a different
> instance of MutationObserver which is mysterious, the code above is the only
> reference to MutationObserver in the extension.
Is inject.js somehow executed several times? That might explain why 2nd argument != observer.

(I know next to nothing how webextensions work)
Flags: needinfo?(bugs)
(In reply to Olli Pettay [:smaug] from comment #9)
> Is inject.js somehow executed several times? That might explain why 2nd
> argument != observer.
> 
> (I know next to nothing how webextensions work)

That was the first thing I checked, the content script is only executed once (verified in a clunky way by loading a version of the extension with some added dump() statements).  To be precise, the mybrowseraddon.com page has a bunch of iframes and the content script is executed once on the main page then also on some of the framed pages, but its only on the main page where we get the neverending flood of callbacks.

I'm willing to try to debug this but I'm inexperienced in using lldb on a Mac.  I thought I would start by just setting a breakpoint in nsDOMMutationObserver::ScheduleForRun() but various attempts at figuring out the right "breakpoint set ..." syntax all failed.
Flags: needinfo?(bugs)
Sorry if this is straightforward, but would it be expected that, when putting the observer stuff (declaration till .observe()-call) in its own scope, `var observer` reproduces, but `let observer` doesn't?
Also, even in the working case the callback is executed a dozen+ times, while it should only be called once due to the disconnect()-call, shouldn't it?
Apparently it doesn't even need an explicit scope, a simple `s/var observer/let observer/` does the trick.
When observer != the 2nd param, what is the value of 2nd param and what is observer?

I wonder if WebExtension scripts are executed somehow in a context which doesn't enter/leave microtask properly and we end up having endless recursion.
Flags: needinfo?(bugs)
Attachment #8890465 - Attachment is obsolete: true
Some evidence that inject.js may be executed twice. I get this output (annotated in [[ ]]):

1 [aswift_1] instance observer:  MutationObserver {  }   [[== temp0]]
2 [aswift_1] instance observer:  MutationObserver {  }   [[== temp1]]
3 [aswift_1]  [[temp2==]] MutationObserver {  }  !=  MutationObserver {  } [[==temp3]](http://mybrowseraddon.com/dark-mode.html)
4+: 19 further times Line 3 (manually limited) - that's when the page hangs and where without limit thousands of messages appear

with temp0 == temp3 and temp1 == temp2 when using this code in the extension:

```
    var n = 0; // limit console output
    var observer = new MutationObserver(function (mutations, argObs) {
        if (n < 20) {
          var id = window.frameElement !== null ? window.frameElement.id : 'TOP';
          var eq = (observer == argObs) ? '==' : '!=';
          console.log("[%s] %o %s %o (%s)", id, observer, eq, argObs, document.baseURI);
        }
        n++;

      if (head) head.appendChild(link);
      observer.disconnect();
    });

    var id = window.frameElement !== null ? window.frameElement.id : 'TOP';
    console.log("[%s] instance observer: %o", id, observer);

    // other stuff elided

    observer.observe(document, {"childList": true, "subtree": true});
```

which would kind of explain why replacing `var` with `let` works, because the second invocation essentially seems to overwrite `window.observer`:

Line 1: first observer set up as window.observer (and callback captures reference to window.observer(?))
Line 2: second observer set up, overwriting window.observer and therefore the callback now sees the 2nd observer
Line 3: Now, the callback sees the second observer as `observer` and the first observer as `argOps` and never calls disconnect() on the original (first) observer.


Big disclaimer: I'm really just poking in the dark here. Why it looks to be executed twice I have no idea and not enough knowledge to investigate further. Note that this is happening not in `window.top`, but a nested one with the same baseURI.
Oh huh, I thought I had checked this before but the script is indeed getting executed multiple times (3 times in the test I have currently set up).  So yeah, we end up with a few different observers and only one of them gets disconnect()ed.  Kris, you've had your fingers in the content script injection code most recently, any thoughts?
Flags: needinfo?(kmaglione+bmo)
Apparently this is because adsbygoogle.js uses document.open multiple times, and we wind up re-injecting the content script for each of them.
Flags: needinfo?(kmaglione+bmo)
Assignee: nobody → kmaglione+bmo
Summary: Dark Mode, Privacy Badger and Google docs make Firefox freeze → document.open()/document.write() execute some content scripts twice in the same sandbox
Comment on attachment 8893595 [details]
Bug 1356273: Part 1 - Set document readyState to uninitialized during document.open()

https://reviewboard.mozilla.org/r/164678/#review170228
Attachment #8893595 - Flags: review?(bugs) → review+
Comment on attachment 8893596 [details]
Bug 1356273: Part 2 - Add tests that document.open()/write() only loads content scripts once.

https://reviewboard.mozilla.org/r/164680/#review170488
Attachment #8893596 - Flags: review?(aswan) → review+
https://hg.mozilla.org/integration/mozilla-inbound/rev/c539ce828bd1b7cd4afbfea74c4819baa8e693f3
Bug 1356273: Part 1 - Set document readyState to uninitialized during document.open() r=smaug

https://hg.mozilla.org/integration/mozilla-inbound/rev/c0c626f34ccc0a5f5726b8e67ba8d2306c813f88
Bug 1356273: Part 2 - Add tests that document.open()/write() only loads content scripts once. r=aswan
https://hg.mozilla.org/mozilla-central/rev/c539ce828bd1
https://hg.mozilla.org/mozilla-central/rev/c0c626f34ccc
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
This bug is verified on Firefox 57.0b9 (20171016185129) under Windows 10 64bit/Ubuntu 16.04 LTS.
Status: RESOLVED → VERIFIED
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.