Broken loading with existing Firefox profile (race condition)

[Juraj-Masiar]

Is this a feature request or a bug?

BUG

What is the current behavior?

1. create a Firefox profile called "Addons"
2. install to this profile your add-on from AMO
3. execute this in your add-on development folder:
   web-ext run --firefox=firefoxdeveloperedition --firefox-profile=Addons --start-url about:debugging

What happened? There is a very high chance that your add-on won't be loaded as Temporary extension (see the about:debugging page). The add-on is loaded from the source files, however the automatic reloading is broken and the background script won't reload on source files change.
This is some king of race condition because there is small chance it will be loaded correctly.

What is the expected or desired behavior?

The add-on should be loaded as Temporary Extension.
The same way as it works with clean profile (without '--firefox-profile' switch').

Version information (for bug reports)

web-ext --version
2.9.1

• Firefox version: 63.0b2 (64-bit) (developer edition)
• Your OS and version: Win 10
• Paste the output of these commands:

node --version && npm --version && web-ext --version

v10.1.0
5.6.0
2.9.1

[rpl]

@icl7126 Let me ask some additional questions to get a better picture of the issue and how to reproduce it:

• is the extension installed from AMO the same one that is installed temporarily from web-ext run?
• is the extension installed by web-ext run built using some transpiling/bundling tools like webpack or babel?
• are there errors logged in Browser Console or in web-ext run --verbose that may suggest which may be the underlying issues?

[Juraj-Masiar]

is the extension installed from AMO the same one that is installed temporarily from web-ext run?
Yes, it's the same add-on. It may have lower version number.

is the extension installed by web-ext run built using some transpiling/bundling tools like webpack or babel?
Kind of... I'm using custom script with NPM. But the web-ext run is executed on folder with normal source files. This folder is not being updated during the web-ext run execution. Only when I change source files, these are copied to this folder and web-ext will correctly reload it (when add-on is correctly loaded).

are there errors logged in Browser Console or in web-ext run --verbose that may suggest which may be the underlying issues?
--verbose output:

C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev>web-ext run --verbose --firefox=firefoxdeveloperedition --firefox-profile=Addons --start-url about:debugging
[program.js][info] Version: 2.9.1
[program.js][debug] Getting the version from package.json
[program.js][debug] Discovering config files. Set --no-config-discovery to disable
[config.js][debug] Discovered config "C:\Users\Juraj\.web-ext-config.js" does not exist or is not readable
[config.js][debug] Discovered config "C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\package.json" does not exist or is not readable
[config.js][debug] Discovered config "C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\web-ext-config.js" does not exist or is not readable
[cmd/run.js][info] Running web extension from C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev
[util/manifest.js][debug] Validating manifest at C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\manifest.json
[extension-runners/firefox-desktop.js][debug] Copying Firefox profile from Addons
[firefox/index.js][debug] Assuming Addons is a named profile
[firefox/index.js][debug] Running Firefox with profile at C:\Users\Juraj\AppData\Local\Temp\65ea20b5-107d-412e-a7e2-02d670bb3bcf
[firefox/index.js][debug] Checking if remote Firefox port 6005 is available
[firefox/remote.js][debug] Connecting to Firefox on port 6005
[firefox/index.js][debug] Executing Firefox binary: C:\Program Files\Firefox Developer Edition\firefox.exe
[firefox/index.js][debug] Firefox args: -start-debugger-server 6005 -foreground -no-remote -profile C:\Users\Juraj\AppData\Local\Temp\65ea20b5-107d-412e-a7e2-02d670bb3bcf --url about:debugging
[firefox/index.js][info] Use --verbose or open Tools > Web Developer > Browser Console to see logging
[firefox/remote.js][debug] Connecting to the remote Firefox debugger
[firefox/remote.js][debug] Connecting to Firefox on port 6005
[firefox/index.js][debug] Firefox stdout: Started debugger server on 6005
[firefox/remote.js][debug] Connected to the remote Firefox debugger on port 6005
[firefox/index.js][debug] Firefox stdout: 1536848938570 addons.xpi      WARN    Addon with ID admin@fastaddons.com_GroupSpeedDial already installed, older version will be disabled
[firefox/remote.js][debug] Received message from client: {"from":"root","type":"tabListChanged"}
[firefox/remote.js][debug] installTemporaryAddon: {"addon":{"id":"admin@fastaddons.com_GroupSpeedDial","actor":false},"from":"server1.conn0.addonsActor3"}
[firefox/remote.js][info] Installed C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev as a temporary add-on
[cmd/run.js][info] The extension will reload if any source file changes
[util/file-filter.js][debug] Resolved path **/*.xpi with sourceDir C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev to C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\**\*.xpi
[util/file-filter.js][debug] Resolved path **/*.zip with sourceDir C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev to C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\**\*.zip
[util/file-filter.js][debug] Resolved path **/.* with sourceDir C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev to C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\**\.*[util/file-filter.js][debug] Resolved path **/.*/**/* with sourceDir C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev to C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\**\.*\**\*
[util/file-filter.js][debug] Resolved path **/node_modules with sourceDir C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev to C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\**\node_modules
[util/file-filter.js][debug] Resolved path **/node_modules/**/* with sourceDir C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev to C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\**\node_modules\**\*
[util/file-filter.js][debug] Ignoring artifacts directory "C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\web-ext-artifacts" and all its subdirectories
[util/file-filter.js][debug] Resolved path C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\web-ext-artifacts with sourceDir C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev to C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\web-ext-artifacts
[util/file-filter.js][debug] Resolved path C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\web-ext-artifacts\**\* with sourceDir C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev to C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\web-ext-artifacts\**\*
[watcher.js][debug] Watching for file changes in C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev
[extension-runners/index.js][info] Press R to reload (and Ctrl-C to quit)
[firefox/index.js][debug] Firefox stderr: JavaScript error: moz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 164: Error: Could not establish connection. Receiving end does not exist.
JavaScript error: moz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 562: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stderr: JavaScript error: reso
[firefox/index.js][debug] Firefox stderr: urce://gre/modules/ExtensionParent.jsm, line 1021: Error: WebExtension context not found!
[util/file-filter.js][debug] Resolved path C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\cs_title.js with sourceDir C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev to C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\cs_title.js
[watcher.js][debug] Changed: C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\cs_title.js
[watcher.js][debug] Last change detection: 16:29:12 GMT+0200 (W. Europe Daylight Time)
[extension-runners/index.js][debug] Reloading add-on at C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev
Last extension reload: 16:29:12 GMT+0200 (W. Europe Daylight Time)[firefox/remote.js][debug]

[firefox/index.js][debug] Firefox stderr: JavaScript error: moz-
[firefox/index.js][debug] Firefox stderr: extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 1: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stderr: J
[firefox/index.js][debug] Firefox stderr: avaScript error: moz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 1: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stderr: JavaScript error: m
[firefox/index.js][debug] Firefox stderr: oz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 1: Error: Could not establish connection. Receiving end does not exist.
[util/file-filter.js][debug] Resolved path C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\cs_title.js with sourceDir C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev to C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\cs_title.js
[watcher.js][debug] Changed: C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\cs_title.js
[watcher.js][debug] Last change detection: 16:29:21 GMT+0200 (W. Europe Daylight Time)
[extension-runners/index.js][debug] Reloading add-on at C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev
Last extension reload: 16:29:21 GMT+0200 (W. Europe Daylight Time)[firefox/remote.js][debug]

[firefox/index.js][debug] Firefox stderr: JavaScript erro
[firefox/index.js][debug] Firefox stderr: r: moz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 1: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stderr: JavaScript error: m
[firefox/index.js][debug] Firefox stderr: oz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 1: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stderr: JavaScript error:
[firefox/index.js][debug] Firefox stderr: moz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 1: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stdout: 1536848966569 addons.xpi      WARN    Addon with ID admin@fastaddons.com_GroupSpeedDial already installed, older version will be disabled
[firefox/remote.js][debug] Received message from client: {"from":"root","type":"addonListChanged"}
[firefox/index.js][debug] Firefox stderr: JavaScript error
[firefox/index.js][debug] Firefox stderr: : moz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 164: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stderr: JavaScript err
[firefox/index.js][debug] Firefox stderr: or: moz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 562: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stderr: JavaScript er
[firefox/index.js][debug] Firefox stderr: ror: resource://gre/modules/ExtensionParent.jsm, line 1021: Error: WebExtension context not found!
[util/file-filter.js][debug] Resolved path C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\cs_title.js with sourceDir C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev to C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\cs_title.js
[watcher.js][debug] Changed: C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\cs_title.js
[watcher.js][debug] Last change detection: 16:29:32 GMT+0200 (W. Europe Daylight Time)
[extension-runners/index.js][debug] Reloading add-on at C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev
[firefox/index.js][debug] Firefox stdout: 1536848973025 addons.xpi      WARN    Addon with ID admin@fastaddons.com_GroupSpeedDial already installed, older version will be disabled
[firefox/remote.js][debug] Received message from client: {"from":"root","type":"addonListChanged"}
Last extension reload: 16:29:33 GMT+0200 (W. Europe Daylight Time)[firefox/remote.js][debug]

[firefox/index.js][debug] Firefox stderr: JavaScript error: m
[firefox/index.js][debug] Firefox stderr: oz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 164: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stderr: JavaScript error: moz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd
[firefox/index.js][debug] Firefox stderr: .js, line 562: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stderr: JavaScript er
[firefox/index.js][debug] Firefox stderr: ror: resource://gre/modules/ExtensionParent.jsm, line 1021: Error: WebExtension context not found!
[util/file-filter.js][debug] Resolved path C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\cs_title.js with sourceDir C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev to C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\cs_title.js
[watcher.js][debug] Changed: C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev\cs_title.js
[watcher.js][debug] Last change detection: 16:29:36 GMT+0200 (W. Europe Daylight Time)
[extension-runners/index.js][debug] Reloading add-on at C:\Users\Juraj\git\addons\GroupSpeedDial\firefox_dev
[firefox/index.js][debug] Firefox stdout: 1536848976748 addons.xpi      WARN    Addon with ID admin@fastaddons.com_GroupSpeedDial already installed, older version will be disabled
[firefox/remote.js][debug] Received message from client: {"from":"root","type":"addonListChanged"}
Last extension reload: 16:29:36 GMT+0200 (W. Europe Daylight Time)[firefox/remote.js][debug]

[firefox/index.js][debug] Firefox stderr: J
[firefox/index.js][debug] Firefox stderr: avaScript error: moz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 164: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stderr: JavaScript erro
[firefox/index.js][debug] Firefox stderr: r: moz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 562: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stderr: J
[firefox/index.js][debug] Firefox stderr: avaScript error: moz-extension://95efecd6-dd6a-4bf6-a9c6-620622bb46e6/background_gsd.js, line 562: Error: Could not establish connection. Receiving end does not exist.
[firefox/index.js][debug] Firefox stderr: JavaScript error: reso
[firefox/index.js][debug] Firefox stderr: urce://gre/modules/ExtensionParent.jsm, line 1021: Error: WebExtension context not found!
[firefox/index.js][debug] Firefox stderr: [Parent 195
[firefox/index.js][debug] Firefox stderr: 80, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
[Child 34020, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_
[firefox/index.js][debug] Firefox stderr: channel_win.cc, line 346
[Child 34020, Chrome_ChildThread] WARNING

Produced by this procedure:
https://youtu.be/4LfYTDOBsG4

My add-on GroupSpeedDial in development mode opens Options page and New tab page - this is done when background script starts. This is how I know my add-on was reloaded.
And as you can see in the video, unless I load the add-on manually using the "Load Temporary Add-on..." button, my add-on won't be correctly reloaded.

[Juraj-Masiar]

I've just noticed one more thing. This Firefox profile I use for development, has also two other add-ons installed. When I run the Firefox with this profile, it all works fine (it's totally clean profile with just these 3 add-ons installed, not being used for anything else).

However when I run this profile with web-ext, all add-ons are wrongly loaded (you can see this in the video - they don't have "Internal UUID" in the about:debugging page). So not just the one I'm developing, but the others that are normally installed through AMO are not working. And when I try to debug them, I get this error log:

Connecting to localhost:26225, ws: false
Start protocol client for connection
Get root form for toolbox
Create toolbox target: {
  "0": {
    "form": {
      "actor": "server3.conn0.webExtension10",
      "id": "juraj.masiar@gmail.com_ScrollAnywhere",
      "name": "ScrollAnywhere",
      "iconURL": "jar:file:///C:/Users/Juraj/AppData/Local/Temp/4793654e-8389-4645-b6a1-10646a766358/extensions/juraj.masiar@gmail.com_ScrollAnywhere.xpi!/48.png",
      "isSystem": false,
      "debuggable": true,
      "temporarilyInstalled": false,
      "type": "extension",
      "isWebExtension": true,
      "manifestURL": null,
      "warnings": []
    },
    "chrome": true,
    "isBrowsingContext": true
  }
}
[object Object]

All of this used to work before, it's probably caused by new Firefox. I'm using now Firefox Developer edition 63.0b4 (64-bit).

[rpl]

Thanks @icl7126 the additional details were very helpful.

Based on some additional logs collected by executing web-ext run with the addition of -p "extensions.logging.enabled=true", it seems that the extension installed in the original profile are being installed but disabled, my guess is that Firefox doesn't like that the pre-existing extensions in the cloned profile have actually an absolute path which points to the original profile.

While we investigate the underlying issue in a bit more detail, you should be able to workaround it by using the additional --keep-profile-changes option, which tells web-ext to use the profile without cloning it:

web-ext run -p /path/to/the/existing-test-profile --keep-profile-changes ...

(currently, because of #932, when using --keep-profile-changes you have to pass the profile path instead of the profile name, but you will be able to use the profile name again once we merge #1149).

[Juraj-Masiar]

Thank you for the workaround - I will make a manual backup now and use the "keep profile changes" switch.
I hope it will be possible to fix it... I really like this feature.

[Juraj-Masiar]

Hello again,
I'm having two more issues that are related to this bug - when using existing profile without keeping profile changes:

1. many times, the whole browser loads broken and cannot load any http(s) page, it will just keep spinning. The only exceptions seems to be pages where content scripts are forbidden, like "https://addons.mozilla.org/".
2. addons installed in the loaded profile appears are not working (I can see them in the about:addons page but they don't have icons on the toolbar and they are not running). This got broken just recently.
   They both feels like race condition, maybe some delay on a right place could help? 😃

node --version && npm --version && web-ext --version
v10.13.0
4.1.1
2.9.3

[Rob--W]

@icl7126 Could you describe in more detail how you created that profile, and if you are able to reproduce the problem with a new problem from scratch, explain the steps to create that profile?

To rule out any changes from web-ext, first try to copy the user profile while preserving attributes (timestamps in particular)`, and start Firefox with that profile. If you use Linux or macOS:

cp -ra /path/to/your/profile /tmp/newdir
firefox --no-remote -profile /tmp/newdir

web-ext run doesn't actually preserve timestamps when it copies the profile, so if the above results in different behavior, try the same, but allow the timestamps to be modified:

cp -r /path/to/your/profile /tmp/anotherdir
firefox --no-remote -profile /tmp/anotherdir

[Juraj-Masiar]

Well the profile is now quite old (I'm add-on developer for more than 2 years now). All profiles I use are created using Firefox profile manager. But the profile was used only for development without saving any changes. I've executed it normally only several times to update add-ons or to install new ones.

I'm gonna try to create a new one, because I can see these two new bugs are not present on my home PC with the same version of web-ext:

v10.1.0
5.6.0
2.9.3

[Juraj-Masiar]

@Rob--W
I've just came to work, updated FF to 66.0b8 (64-bit) and now just like magic it works.
I would like to point out that I don't reboot my PC, I use hibernation so only thing that changed since Friday is restarting main browser to update it.

Is there some connection between my main Firefox profile and my testing profile? They both use same instance of Firefox Developer Edition, but they are distinct profiles.
I've noticed some strange issues just like this in the past where I had to close my main Firefox just to fix it.

[Rob--W]

Is there some connection between my main Firefox profile and my testing profile?

Unless you explicitly select your main profile (via -p), a new profile is created (either from scratch). By default the profile is copied, but if you pass --keep-profile-changes the changes may be saved.

Sometimes bugs only occur once after a version update (potentially related to profile-specific caching startup state, which is reset on updates), so if you want to reproduce the bug, you can consider making a backup of your test profile directory (while preserving attributes, timestamps in particular) before running the test.

[Juraj-Masiar]

@Rob--W
The bug is back and I can now reproduce it with a new profile.
I've also made a video:
https://youtu.be/8sExSpyohZg

Steps:

1. create new profile called "b"
2. run the profile
3. install some addons to this profile, for example uBlock
4. close Firefox
5. execute following command in any web-extension directory:
   web-ext run --firefox=firefoxdeveloperedition --firefox-profile=b --start-url about:debugging
6. see that the uBlock is loaded
7. close Firefox
8. open Firefox with "b" profile
9. close Firefox
10. execute again the command from the step 5
11. see that uBlock is no longer being loaded

EDIT:
I can reproduce it also on my home PC. Somehow after executing the profile second time after its creation something breaks and web-ext is no longer able to load those add-ons.

EDIT 2:
And again, after updating to 66.0b9 it works again. Seems like your theory with profile-specific caching startup state is correct.

[Rob--W]

@icl7126 Are you using a localized (non-English) version of Firefox? If so, it may be related to #1498 and https://bugzilla.mozilla.org/show_bug.cgi?id=1524679

If not, can you also reproduce if you do not use the profile manager, but a path to the directory? In the Bugzilla bug I put down some very explicit reproduction steps (in multiple comments).

[Juraj-Masiar]

@Rob--W
I'm using normal English version of Developer Edition.
I've copied one of the "broken" profiles to a new folder, executed recursive touch on all files and run:

web-ext run --firefox=firefoxdeveloperedition -p c:/tmp/profdir --start-url about:debugging

But it's still broken - the add-ons appears for a moment on a toolbar and then disappears.