1477550 - Automation quit from Marionette causes JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 683: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "Flush WebExtension StartupCache"

Status: NEW

(Firefox :: Screenshots, defect)

Description

[Andreas Tolfsen ❲:ato❳]

The Marionette remote protocol exposes an API that geckodriver (our
WebDriver implementation) uses for shutting down Firefox.  It uses
eForceQuit to ensure Firefox is terminated.

An excerpt from running the WPT test suite with full logs enabled
shows that the web extension AsyncShutdown.jsm module spews out a
long error message:

>  0:17.87 pid:11354 1532266126821	webdriver::server	DEBUG	-> DELETE /session/61f1c0df-afce-4ec2-aad1-820417d4c4e4
>  0:17.89 pid:11354 1532266126842	Marionette	TRACE	0 -> [0,2,"Marionette:Quit",{"flags":["eForceQuit"]}]
>  0:17.90 pid:11354 1532266126843	Marionette	INFO	Stopped listening on port 2828
>  0:17.93 pid:11354 1532266126871	Marionette	TRACE	0 <- [1,2,null,{"cause":"shutdown"}]
>  0:17.95 pid:11354 1532266126897	webdriver::server	DEBUG	Deleting session
>  0:17.95 pid:11354 1532266126900	Marionette	TRACE	0 -> [0,3,"Marionette:Quit",{"flags":["eForceQuit"]}]
>  0:17.95 pid:11354 1532266126901	Marionette	TRACE	0 <- [1,3,{"error":"invalid session id","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:178:5\nInva ... et@chrome://marionette/content/server.js:245:8\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:490:9\n"},null]
>  0:17.97 pid:11354 1532266126912	Marionette	DEBUG	Closed connection 0
>  0:18.13 pid:11354 1532266127068	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
>  0:18.13 pid:11354 1532266127068	Marionette	DEBUG	Resetting recommended pref security.turn_off_all_security_so_that_viruses_can_take_over_this_computer
>  0:18.13 pid:11354 1532266127068	Marionette	DEBUG	Resetting recommended pref apz.content_response_timeout
>  0:18.13 pid:11354 1532266127068	Marionette	DEBUG	Resetting recommended pref browser.download.panel.shown
>  0:18.13 pid:11354 1532266127069	Marionette	DEBUG	Resetting recommended pref browser.pagethumbnails.capturing_disabled
>  0:18.13 pid:11354 1532266127069	Marionette	DEBUG	Resetting recommended pref browser.search.update
>  0:18.13 pid:11354 1532266127069	Marionette	DEBUG	Resetting recommended pref toolkit.cosmeticAnimations.enabled
>  0:18.13 pid:11354 1532266127069	Marionette	DEBUG	Resetting recommended pref browser.tabs.disableBackgroundZombification
>  0:18.13 pid:11354 1532266127069	Marionette	DEBUG	Resetting recommended pref browser.tabs.warnOnCloseOtherTabs
>  0:18.13 pid:11354 1532266127069	Marionette	DEBUG	Resetting recommended pref browser.tabs.warnOnOpen
>  0:18.13 pid:11354 1532266127069	Marionette	DEBUG	Resetting recommended pref browser.usedOnWindows10.introURL
>  0:18.13 pid:11354 1532266127070	Marionette	DEBUG	Resetting recommended pref browser.urlbar.suggest.searches
>  0:18.13 pid:11354 1532266127070	Marionette	DEBUG	Resetting recommended pref datareporting.policy.dataSubmissionPolicyAccepted
>  0:18.13 pid:11354 1532266127071	Marionette	DEBUG	Resetting recommended pref dom.disable_beforeunload
>  0:18.13 pid:11354 1532266127072	Marionette	DEBUG	Resetting recommended pref dom.disable_open_during_load
>  0:18.13 pid:11354 1532266127072	Marionette	DEBUG	Resetting recommended pref dom.file.createInChild
>  0:18.13 pid:11354 1532266127072	Marionette	DEBUG	Resetting recommended pref dom.max_chrome_script_run_time
>  0:18.13 pid:11354 1532266127072	Marionette	DEBUG	Resetting recommended pref dom.max_script_run_time
>  0:18.13 pid:11354 1532266127073	Marionette	DEBUG	Resetting recommended pref extensions.getAddons.cache.enabled
>  0:18.13 pid:11354 1532266127073	Marionette	DEBUG	Resetting recommended pref extensions.webservice.discoverURL
>  0:18.13 pid:11354 1532266127073	Marionette	DEBUG	Resetting recommended pref network.http.prompt-temp-redirect
>  0:18.13 pid:11354 1532266127073	Marionette	DEBUG	Resetting recommended pref network.http.speculative-parallel-limit
>  0:18.13 pid:11354 1532266127073	Marionette	DEBUG	Resetting recommended pref security.fileuri.strict_origin_policy
>  0:18.13 pid:11354 1532266127073	Marionette	DEBUG	Resetting recommended pref security.notification_enable_delay
>  0:18.13 pid:11354 1532266127073	Marionette	DEBUG	Resetting recommended pref signon.autofillForms
>  0:18.13 pid:11354 1532266127073	Marionette	DEBUG	Resetting recommended pref signon.rememberSignons
>  0:18.13 pid:11354 1532266127073	Marionette	DEBUG	Remote service is inactive
>  0:18.16 pid:11354 Extension error: Data is not ready. resource://gre/modules/JSONFile.jsm:159 :: get data@resource://gre/modules/JSONFile.jsm:159:13
>  0:18.16 pid:11354 _get@resource://gre/modules/ExtensionPermissions.jsm:63:9
>  0:18.16 pid:11354 async*_getCached/<@resource://gre/modules/ExtensionPermissions.jsm:74:47
>  0:18.16 pid:11354 get@resource://gre/modules/ExtensionParent.jsm:1684:22
>  0:18.16 pid:11354 async*_getCached@resource://gre/modules/ExtensionPermissions.jsm:73:12
>  0:18.16 pid:11354 async*get@resource://gre/modules/ExtensionPermissions.jsm:78:12
>  0:18.16 pid:11354 parseManifest@resource://gre/modules/Extension.jsm:659:27
>  0:18.16 pid:11354 async*_parseManifest@resource://gre/modules/Extension.jsm:1491:26
>  0:18.16 pid:11354 async*parseManifest/<@resource://gre/modules/Extension.jsm:1507:68
>  0:18.16 pid:11354 get@resource://gre/modules/ExtensionParent.jsm:1684:22
>  0:18.16 pid:11354 async*parseManifest@resource://gre/modules/Extension.jsm:1507:12
>  0:18.16 pid:11354 loadManifest@resource://gre/modules/Extension.jsm:809:7
>  0:18.16 pid:11354 async*loadManifest@resource://gre/modules/Extension.jsm:1519:26
>  0:18.16 pid:11354 async*startup@resource://gre/modules/Extension.jsm:1752:13
>  0:18.16 pid:11354 async*startup/this.startupPromise<@resource://gre/modules/LegacyExtensionsUtils.jsm:195:7
>  0:18.16 pid:11354 startup@resource://gre/modules/LegacyExtensionsUtils.jsm:142:27
>  0:18.16 pid:11354 start@resource://gre/modules/addons/XPIProvider.jsm -> file:///home/ato/src/gecko/obj-x86_64-pc-linux-gnu/dist/bin/browser/features/[e-mail]/bootstrap.js:178:10
>  0:18.16 pid:11354 handleStartup@resource://gre/modules/addons/XPIProvider.jsm -> file:///home/ato/src/gecko/obj-x86_64-pc-linux-gnu/dist/bin/browser/features/[e-mail]/bootstrap.js:171:5
>  0:18.16 pid:11354 promise callback*startup@resource://gre/modules/addons/XPIProvider.jsm -> file:///home/ato/src/gecko/obj-x86_64-pc-linux-gnu/dist/bin/browser/features/[e-mail]/bootstrap.js:134:23
>  0:18.16 pid:11354 callBootstrapMethod@resource://gre/modules/addons/XPIProvider.jsm:1588:20
>  0:18.16 pid:11354 async*startup@resource://gre/modules/addons/XPIProvider.jsm:1703:27
>  0:18.16 pid:11354 async*startup@resource://gre/modules/addons/XPIProvider.jsm:2150:13
>  0:18.16 pid:11354 callProvider@resource://gre/modules/AddonManager.jsm:206:12
>  0:18.16 pid:11354 _startProvider@resource://gre/modules/AddonManager.jsm:654:5
>  0:18.16 pid:11354 startup@resource://gre/modules/AddonManager.jsm:813:9
>  0:18.16 pid:11354 startup@resource://gre/modules/AddonManager.jsm:2811:5
>  0:18.16 pid:11354 observe@file:///home/ato/src/gecko/obj-x86_64-pc-linux-gnu/dist/bin/components/addonManager.js:66:9
>  0:18.16 pid:11354 
>  0:18.16 pid:11354 JavaScript error: resource://gre/modules/osfile/osfile_async_front.jsm, line 408: Error: OS.File has been shut down. Rejecting post to DirectoryIterator_prototype_close
>  0:18.16 pid:11354 JavaScript error: resource://gre/modules/osfile/osfile_async_front.jsm, line 408: Error: OS.File has been shut down. Rejecting post to DirectoryIterator_prototype_close
>  0:18.16 pid:11354 JavaScript error: resource://gre/modules/osfile/osfile_async_front.jsm, line 408: Error: OS.File has been shut down. Rejecting post to DirectoryIterator_prototype_close
>  0:18.16 pid:11354 JavaScript error: resource://gre/modules/ProfileAge.jsm, line 197: Error: Unable to fetch oldest profile entry: Error: OS.File has been shut down. Rejecting request to DirectoryIterator_prototype_next
>  0:18.16 pid:11354 JavaScript error: resource://gre/modules/osfile/osfile_async_front.jsm, line 408: Error: OS.File has been shut down. Rejecting post to makeDir
>  0:18.16 pid:11354 JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 683: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "Flush WebExtension StartupCache"
>  0:18.16 pid:11354 JavaScript error: resource://gre/modules/ProfileAge.jsm, line 197: Error: Unable to fetch oldest profile entry: Error: OS.File has been shut down. Rejecting post to DirectoryIterator_prototype_next

This can be reproduced with running for example:

> % MOZ_HEADLESS=1 ./mach wpt  --manifest-update testing/web-platform/tests/webdriver/tests/new_session/create_alwaysMatch.py --webdriver-arg="-vv"

My question is if there’s anything we can do about this to ensure
web extensions are properly cleaned up and shutdown before Marionette
attempts to quit Firefox?

Comment 1

[David Teller [:Yoric] - still alive but not very active]

Two things:

- AsyncShutdown is *not* a WebExtension, it is part of the shutdown mechanism of Firefox itself;

- The code that causes the message "Flush WebExtension StartupCache" is here: https://searchfox.org/mozilla-central/source/toolkit/components/extensions/ExtensionParent.jsm#1584. Apparently, something calls `StartupCache.save` (too late) during shutdown. It should register its blockers earlier.

ni? aswan, who wrote that specific line

Comment 2

[Andrew Swan [:aswan]]

It looks like screenshots is doing its delayed-startup-of-the-webextension after browser shutdown has already begun.
If nothing else, bug 1422437 should take care of this.