Closed Bug 1755063 Opened 3 years ago Closed 3 years ago

Intermittent browser/components/migration/tests/marionette/test_refresh_firefox.py TestFirefoxRefresh.testResetEverything | AssertionError: Sequences differ: ['about:blank'] != ['about:welcomeback']

Categories

(Firefox :: Migration, defect, P5)

Product:
Firefox
Component:
Migration
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: assertion, intermittent-failure)

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=367595574&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/T6pBCMI-SiOicR5sJ1K7oA/runs/0/artifacts/public/logs/live_backing.log

[task 2022-02-11T18:06:42.210Z] 18:06:42     INFO -  ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-11T18:06:42.967Z] 18:06:42     INFO -  [CodeCoverage] Setting handlers for process 22547.
[task 2022-02-11T18:06:50.844Z] 18:06:50     INFO -  DEBUG: Completed blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2022-02-11T18:06:51.078Z] 18:06:51     INFO -  DEBUG: Adding blocker MediaShutdownManager: shutdown for phase profile-before-change
[task 2022-02-11T18:06:51.275Z] 18:06:51     INFO -  DEBUG: Adding blocker GMPProvider for phase AddonManager: Waiting for providers to shut down.
[task 2022-02-11T18:06:51.278Z] 18:06:51     INFO -  DEBUG: Adding blocker ContentParent: id=7fbe87d80500 for phase xpcom-will-shutdown
[task 2022-02-11T18:06:51.279Z] 18:06:51     INFO -  DEBUG: Adding blocker ContentParent: id=7fbe87d80500 for phase profile-before-change
[task 2022-02-11T18:06:51.432Z] 18:06:51     INFO -  DEBUG: Adding blocker ContentParent: id=7fbe7e343600 for phase xpcom-will-shutdown
[task 2022-02-11T18:06:51.434Z] 18:06:51     INFO -  DEBUG: Adding blocker ContentParent: id=7fbe7e343600 for phase profile-before-change
[task 2022-02-11T18:06:51.461Z] 18:06:51     INFO -  DEBUG: Adding blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2022-02-11T18:06:51.462Z] 18:06:51     INFO -  DEBUG: Completed blocker TelemetryController: removing pending pings after data upload was disabled for phase TelemetryController: Waiting for clients.
[task 2022-02-11T18:06:51.589Z] 18:06:51     INFO -  DEBUG: Adding blocker Remote Settings profile-before-change for phase profile-before-change
[task 2022-02-11T18:06:51.591Z] 18:06:51     INFO -  DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-11T18:06:51.616Z] 18:06:51     INFO -  DEBUG: Completed blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2022-02-11T18:06:51.733Z] 18:06:51     INFO -  DEBUG: Adding blocker PageActions: purging unregistered actions from cache for phase profile-before-change
[task 2022-02-11T18:06:51.748Z] 18:06:51     INFO -  DEBUG: Adding blocker Places Clients shutdown for phase profile-change-teardown
[task 2022-02-11T18:06:51.749Z] 18:06:51     INFO -  DEBUG: Adding blocker Places Connection shutdown for phase profile-before-change
[task 2022-02-11T18:06:51.992Z] 18:06:51     INFO -  DEBUG: Adding blocker ContentParent: id=7fbe77623700 for phase xpcom-will-shutdown
[task 2022-02-11T18:06:51.994Z] 18:06:51     INFO -  DEBUG: Adding blocker ContentParent: id=7fbe77623700 for phase profile-before-change
[task 2022-02-11T18:06:52.237Z] 18:06:52     INFO -  DEBUG: Adding blocker sanitize.js: Sanitize on shutdown for phase Places Clients shutdown
[task 2022-02-11T18:06:52.276Z] 18:06:52     INFO -  console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /builds/worker/.mozilla/firefox/rzi8e5hm.marionette-test-profile-1644602800831-1644602803044/search.json.mozlz4", (void 0)))
[task 2022-02-11T18:06:52.291Z] 18:06:52     INFO -  DEBUG: Adding blocker Sqlite.jsm shutdown blocker for phase profile-before-change
[task 2022-02-11T18:06:52.292Z] 18:06:52     INFO -  DEBUG: Adding blocker places.sqlite#1: waiting for shutdown for phase Sqlite.jsm: wait until all connections are closed
[task 2022-02-11T18:06:52.293Z] 18:06:52     INFO -  DEBUG: Adding blocker Places Expiration: shutdown for phase Places Connection shutdown
[task 2022-02-11T18:06:52.293Z] 18:06:52     INFO -  DEBUG: Adding blocker PlacesUtils wrapped connection closing as part of Places shutdown for phase Places Connection shutdown
[task 2022-02-11T18:06:52.294Z] 18:06:52     INFO -  DEBUG: Adding blocker PlacesUtils wrapped connection must be closed before Sqlite.jsm for phase Sqlite.jsm: wait until all clients have completed their task
[task 2022-02-11T18:06:52.295Z] 18:06:52     INFO -  DEBUG: Adding blocker places.sqlite#1: PlacesExpiration.jsm: setup (0) for phase places.sqlite#1: waiting for clients
[task 2022-02-11T18:06:52.295Z] 18:06:52     INFO -  DEBUG: Adding blocker places.sqlite#0: waiting for shutdown for phase Sqlite.jsm: wait until all connections are closed
[task 2022-02-11T18:06:52.296Z] 18:06:52     INFO -  DEBUG: Adding blocker PlacesUtils read-only connection closing as part of Places shutdown for phase Places Connection shutdown
[task 2022-02-11T18:06:52.296Z] 18:06:52     INFO -  DEBUG: Adding blocker PlacesUtils read-only connection must be closed before Sqlite.jsm for phase Sqlite.jsm: wait until all clients have completed their task
[task 2022-02-11T18:06:52.329Z] 18:06:52     INFO -  DEBUG: Completed blocker places.sqlite#1: PlacesExpiration.jsm: setup (0) for phase places.sqlite#1: waiting for clients
[task 2022-02-11T18:06:52.376Z] 18:06:52     INFO -  [CodeCoverage] Setting handlers for process 22641.
[task 2022-02-11T18:06:52.420Z] 18:06:52     INFO -  JavaScript error: resource://gre/modules/PromiseWorker.jsm, line 106: Error: Could not get children of file(/builds/worker/.mozilla/firefox/rzi8e5hm.marionette-test-profile-1644602800831-1644602803044/thumbnails) because it does not exist
[task 2022-02-11T18:06:52.440Z] 18:06:52     INFO -  DEBUG: Adding blocker ContextualIdentityService: writing data for phase profile-before-change
[task 2022-02-11T18:06:52.535Z] 18:06:52     INFO -  DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-11T18:06:52.560Z] 18:06:52     INFO -  DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-11T18:06:52.689Z] 18:06:52     INFO -  DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-11T18:06:52.764Z] 18:06:52     INFO -  [CodeCoverage] Setting handlers for process 22644.
[task 2022-02-11T18:06:52.795Z] 18:06:52     INFO -  DEBUG: Adding blocker places.sqlite#1: PlacesUIUtils: maybeAddImportButton (1) for phase places.sqlite#1: waiting for clients
[task 2022-02-11T18:06:52.796Z] 18:06:52     INFO -  DEBUG: Completed blocker places.sqlite#1: PlacesUIUtils: maybeAddImportButton (1) for phase places.sqlite#1: waiting for clients
[task 2022-02-11T18:06:52.893Z] 18:06:52     INFO -  1644602812891	FirefoxAccounts	ERROR	checkEmailStatus failed to poll: Error: checkEmailStatus called without a session token(resource://gre/modules/FxAccounts.jsm:899:9) JS Stack trace: checkEmailStatus@FxAccounts.jsm:899:9
[task 2022-02-11T18:06:52.894Z] 18:06:52     INFO -  pollEmailStatus@FxAccounts.jsm:1227:35
[task 2022-02-11T18:06:52.894Z] 18:06:52     INFO -  startPollEmailStatus@FxAccounts.jsm:1218:17
[task 2022-02-11T18:06:52.894Z] 18:06:52     INFO -  whenVerified@FxAccounts.jsm:1168:12
[task 2022-02-11T18:06:52.894Z] 18:06:52     INFO -  startVerifiedCheck@FxAccounts.jsm:1155:10
[task 2022-02-11T18:06:52.894Z] 18:06:52     INFO -  getSignedInUser/<@FxAccounts.jsm:553:24
[task 2022-02-11T18:06:52.895Z] 18:06:52     INFO -  1644602812892	FirefoxAccounts	ERROR	checkEmailStatus failed to poll: Error: checkEmailStatus called without a session token(resource://gre/modules/FxAccounts.jsm:899:9) JS Stack trace: checkEmailStatus@FxAccounts.jsm:899:9
[task 2022-02-11T18:06:52.895Z] 18:06:52     INFO -  pollEmailStatus@FxAccounts.jsm:1227:35
[task 2022-02-11T18:06:52.895Z] 18:06:52     INFO -  startPollEmailStatus@FxAccounts.jsm:1218:17
[task 2022-02-11T18:06:52.895Z] 18:06:52     INFO -  loadAndPoll/<@FxAccounts.jsm:1132:16
[task 2022-02-11T18:06:52.897Z] 18:06:52     INFO -  console.info: "Skipping device list refresh; not signed in"
[task 2022-02-11T18:06:52.942Z] 18:06:52     INFO -  1644602812941	Marionette	INFO	Listening on port 2828
[task 2022-02-11T18:06:52.977Z] 18:06:52     INFO -  DEBUG: Adding blocker DownloadAutoSaveView: writing data for phase profile-before-change
[task 2022-02-11T18:06:52.986Z] 18:06:52     INFO -  DEBUG: Adding blocker ScriptPreloader: Saving bytecode cache for phase xpcom-will-shutdown
[task 2022-02-11T18:06:53.349Z] 18:06:53     INFO -  Missing chrome or resource URL: resource://formautofill/FormAutofillStorage.jsm
[task 2022-02-11T18:06:53.381Z] 18:06:53     INFO -  DEBUG: Adding blocker places.sqlite#1: Bookmarks.jsm: fetchBookmarksByURL (2) for phase places.sqlite#1: waiting for clients
[task 2022-02-11T18:06:53.383Z] 18:06:53     INFO -  DEBUG: Completed blocker places.sqlite#1: Bookmarks.jsm: fetchBookmarksByURL (2) for phase places.sqlite#1: waiting for clients
[task 2022-02-11T18:06:53.401Z] 18:06:53     INFO -  DEBUG: Adding blocker formhistory.sqlite#0: waiting for shutdown for phase Sqlite.jsm: wait until all connections are closed
[task 2022-02-11T18:06:53.401Z] 18:06:53     INFO -  DEBUG: Adding blocker Closing FormHistory database. for phase Sqlite.jsm: wait until all clients have completed their task
[task 2022-02-11T18:06:53.448Z] 18:06:53     INFO -  [CodeCoverage] Setting handlers for process 22652.
[task 2022-02-11T18:06:53.580Z] 18:06:53     INFO -  DEBUG: Adding blocker content-prefs.sqlite#0: waiting for shutdown for phase Sqlite.jsm: wait until all connections are closed
[task 2022-02-11T18:06:53.582Z] 18:06:53     INFO -  DEBUG: Adding blocker Closing ContentPrefService2 connection. for phase Sqlite.jsm: wait until all clients have completed their task
[task 2022-02-11T18:06:53.587Z] 18:06:53     INFO -  DEBUG: Adding blocker Transaction (0) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-02-11T18:06:53.685Z] 18:06:53     INFO -  JavaScript error: resource://gre/modules/URLQueryStrippingListService.jsm, line 90: TypeError: can't access property "removeEventListener", Services.cpmm.sharedData is null
[task 2022-02-11T18:06:53.687Z] 18:06:53     INFO -  ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-11T18:06:53.687Z] 18:06:53     INFO -  ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO - TEST-UNEXPECTED-FAIL | browser/components/migration/tests/marionette/test_refresh_firefox.py TestFirefoxRefresh.testResetEverything | AssertionError: Sequences differ: ['about:blank'] != ['about:welcomeback']
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO - 
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO - First differing element 0:
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO - 'about:blank'
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO - 'about:welcomeback'
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO - 
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO - - ['about:blank']
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO - + ['about:welcomeback']
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO - Traceback (most recent call last):
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py", line 202, in run
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO -     testMethod()
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/browser/components/migration/tests/marionette/test_refresh_firefox.py", line 688, in testResetEverything
[task 2022-02-11T18:06:53.862Z] 18:06:53     INFO -     self.checkProfile(has_migrated=True, expect_sync_user=True)
[task 2022-02-11T18:06:53.863Z] 18:06:53     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/browser/components/migration/tests/marionette/test_refresh_firefox.py", line 512, in checkProfile
[task 2022-02-11T18:06:53.863Z] 18:06:53     INFO -     self.checkSession()
[task 2022-02-11T18:06:53.863Z] 18:06:53     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/browser/components/migration/tests/marionette/test_refresh_firefox.py", line 427, in checkSession
[task 2022-02-11T18:06:53.863Z] 18:06:53     INFO -     self.assertSequenceEqual(tabURIs, ["about:welcomeback"])
[task 2022-02-11T18:06:53.863Z] 18:06:53     INFO - TEST-INFO took 13568ms
[task 2022-02-11T18:06:53.890Z] 18:06:53     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /tmp/tmpgpdup0ix.mozrunner
[task 2022-02-11T18:06:53.952Z] 18:06:53     INFO -  [CodeCoverage] Setting handlers for process 22746.
[task 2022-02-11T18:06:54.156Z] 18:06:54     INFO -  DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2022-02-11T18:06:54.195Z] 18:06:54     INFO -  DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase profile-before-change
[task 2022-02-11T18:06:54.196Z] 18:06:54     INFO -  DEBUG: Adding blocker IOUtils Blocker (xpcom-will-shutdown) for phase xpcom-will-shutdown
[task 2022-02-11T18:06:54.256Z] 18:06:54     INFO -  DEBUG: Adding blocker Flush WebExtension StartupCache for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-11T18:06:54.448Z] 18:06:54     INFO -  DEBUG: Adding blocker JSON store: writing data for phase AddonManager: Waiting for providers to shut down.
[task 2022-02-11T18:06:54.454Z] 18:06:54     INFO -  DEBUG: Adding blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2022-02-11T18:06:54.464Z] 18:06:54     INFO -  DEBUG: Adding blocker XPIProvider shutdown for phase quit-application-granted
[task 2022-02-11T18:06:54.466Z] 18:06:54     INFO -  DEBUG: Adding blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2022-02-11T18:06:54.467Z] 18:06:54     INFO -  DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2022-02-11T18:06:54.470Z] 18:06:54     INFO -  DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change and awaiting all checkpoints written for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-11T18:06:54.498Z] 18:06:54     INFO -  DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2022-02-11T18:06:54.720Z] 18:06:54     INFO -  DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2022-02-11T18:06:54.738Z] 18:06:54     INFO -  DEBUG: Adding blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2022-02-11T18:06:54.746Z] 18:06:54     INFO -  1644602814745	Marionette	INFO	Marionette enabled
[task 2022-02-11T18:06:54.848Z] 18:06:54     INFO -  DEBUG: Adding blocker PermissionManager: Flushing data for phase xpcom-will-shutdown
[task 2022-02-11T18:06:54.862Z] 18:06:54     INFO -  1644602814862	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2022-02-11T18:06:54.874Z] 18:06:54     INFO -  DEBUG: Completed blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2022-02-11T18:06:54.879Z] 18:06:54     INFO -  DEBUG: Adding blocker ClientManagerService: start destroying IPC actors early for phase xpcom-will-shutdown
[task 2022-02-11T18:06:55.363Z] 18:06:55     INFO -  DEBUG: Adding blocker MediaShutdownManager: shutdown for phase profile-before-change
[task 2022-02-11T18:06:55.627Z] 18:06:55     INFO -  DEBUG: Adding blocker GMPProvider for phase AddonManager: Waiting for providers to shut down.
[task 2022-02-11T18:06:55.648Z] 18:06:55     INFO -  DEBUG: Adding blocker ContentParent: id=7fabd23af700 for phase xpcom-will-shutdown
[task 2022-02-11T18:06:55.649Z] 18:06:55     INFO -  DEBUG: Adding blocker ContentParent: id=7fabd23af700 for phase profile-before-change
[task 2022-02-11T18:06:55.836Z] 18:06:55     INFO -  DEBUG: Adding blocker ServiceWorkerShutdownBlocker: shutting down Service Workers for phase profile-change-teardown
[task 2022-02-11T18:06:55.879Z] 18:06:55     INFO -  DEBUG: Adding blocker ContentParent: id=7fabf18f9000 for phase xpcom-will-shutdown
[task 2022-02-11T18:06:55.879Z] 18:06:55     INFO -  DEBUG: Adding blocker ContentParent: id=7fabf18f9000 for phase profile-before-change
[task 2022-02-11T18:06:55.928Z] 18:06:55     INFO -  DEBUG: Adding blocker Remote Settings profile-before-change for phase profile-before-change
[task 2022-02-11T18:06:56.315Z] 18:06:56     INFO -  [CodeCoverage] Setting handlers for process 22826.
[task 2022-02-11T18:06:56.505Z] 18:06:56     INFO -  [CodeCoverage] Setting handlers for process 22829.
[task 2022-02-11T18:06:57.023Z] 18:06:57     INFO -  DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-11T18:06:59.007Z] 18:06:59     INFO -  DEBUG: Adding blocker PageActions: purging unregistered actions from cache for phase profile-before-change
[task 2022-02-11T18:06:59.024Z] 18:06:59     INFO -  DEBUG: Adding blocker Places Clients shutdown for phase profile-change-teardown
[task 2022-02-11T18:06:59.024Z] 18:06:59     INFO -  DEBUG: Adding blocker Places Connection shutdown for phase profile-before-change
[task 2022-02-11T18:06:59.052Z] 18:06:59     INFO -  DEBUG: Adding blocker sanitize.js: Sanitize on shutdown for phase Places Clients shutdown
[task 2022-02-11T18:06:59.098Z] 18:06:59     INFO -  console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpgpdup0ix.mozrunner/search.json.mozlz4", (void 0)))
[task 2022-02-11T18:06:59.151Z] 18:06:59     INFO -  DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-11T18:06:59.190Z] 18:06:59     INFO -  DEBUG: Adding blocker Sqlite.jsm shutdown blocker for phase profile-before-change
[task 2022-02-11T18:06:59.191Z] 18:06:59     INFO -  DEBUG: Adding blocker content-prefs.sqlite#0: waiting for shutdown for phase Sqlite.jsm: wait until all connections are closed
[task 2022-02-11T18:06:59.192Z] 18:06:59     INFO -  DEBUG: Adding blocker Closing ContentPrefService2 connection. for phase Sqlite.jsm: wait until all clients have completed their task
[task 2022-02-11T18:06:59.201Z] 18:06:59     INFO -  DEBUG: Adding blocker Transaction (0) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-02-11T18:06:59.305Z] 18:06:59     INFO -  DEBUG: Completed blocker Transaction (0) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-02-11T18:06:59.306Z] 18:06:59     INFO -  DEBUG: Adding blocker Transaction (1) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-02-11T18:06:59.307Z] 18:06:59     INFO -  DEBUG: Adding blocker Transaction (2) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-02-11T18:06:59.338Z] 18:06:59     INFO -  DEBUG: Adding blocker ContentParent: id=7fabc6fd5e00 for phase xpcom-will-shutdown
[task 2022-02-11T18:06:59.340Z] 18:06:59     INFO -  DEBUG: Adding blocker ContentParent: id=7fabc6fd5e00 for phase profile-before-change
[task 2022-02-11T18:06:59.351Z] 18:06:59     INFO -  DEBUG: Completed blocker Transaction (1) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-02-11T18:06:59.403Z] 18:06:59     INFO -  DEBUG: Completed blocker Transaction (2) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-02-11T18:06:59.507Z] 18:06:59     INFO -  DEBUG: Adding blocker ContextualIdentityService: writing data for phase profile-before-change
[task 2022-02-11T18:06:59.543Z] 18:06:59     INFO -  DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-11T18:06:59.638Z] 18:06:59     INFO -  DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-11T18:07:00.183Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: waiting for shutdown for phase Sqlite.jsm: wait until all connections are closed
[task 2022-02-11T18:07:00.184Z] 18:07:00     INFO -  DEBUG: Adding blocker PlacesUtils wrapped connection closing as part of Places shutdown for phase Places Connection shutdown
[task 2022-02-11T18:07:00.184Z] 18:07:00     INFO -  DEBUG: Adding blocker PlacesUtils wrapped connection must be closed before Sqlite.jsm for phase Sqlite.jsm: wait until all clients have completed their task
[task 2022-02-11T18:07:00.194Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: PlacesUIUtils: maybeAddImportButton (0) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.204Z] 18:07:00     INFO -  DEBUG: Adding blocker Places Expiration: shutdown for phase Places Connection shutdown
[task 2022-02-11T18:07:00.207Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: PlacesExpiration.jsm: setup (1) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.207Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: PlacesUIUtils: maybeAddImportButton (0) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.214Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: PlacesExpiration.jsm: setup (1) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.261Z] 18:07:00     INFO -  DEBUG: Adding blocker OS.File: flush pending requests, warn about unclosed files, shut down service. for phase xpcom-will-shutdown
[task 2022-02-11T18:07:00.262Z] 18:07:00     INFO -  DEBUG: Adding blocker OS.File: flush I/O queued before profileBeforeChange for phase profile-before-change
[task 2022-02-11T18:07:00.297Z] 18:07:00     INFO -  DEBUG: Adding blocker Transaction (2) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.298Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: Bookmarks.jsm: eraseEverything (3) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.324Z] 18:07:00     INFO -  DEBUG: Completed blocker Transaction (2) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.330Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: Bookmarks.jsm: eraseEverything (3) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.331Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: Bookmarks.jsm: fetchBookmark (4) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.332Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: Bookmarks.jsm: fetchBookmark (4) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.333Z] 18:07:00     INFO -  DEBUG: Adding blocker Transaction (5) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.334Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: Bookmarks.jsm: insertBookmarkTree (6) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.351Z] 18:07:00     INFO -  DEBUG: Completed blocker Transaction (5) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.352Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: Bookmarks.jsm: insertBookmarkTree (6) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.353Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: GuidHelper.getItemId (7) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.356Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: GuidHelper.getItemId (7) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.358Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: PlacesUtils.keywords.insert (8) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.359Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: PlacesUtils: promiseKeywordsCache (9) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.360Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: PlacesUtils: promiseKeywordsCache (9) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.361Z] 18:07:00     INFO -  DEBUG: Adding blocker Transaction (10) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.411Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: Bookmarks.jsm: fetchBookmarksByURL (11) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.411Z] 18:07:00     INFO -  DEBUG: Completed blocker Transaction (10) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.414Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#1: waiting for shutdown for phase Sqlite.jsm: wait until all connections are closed
[task 2022-02-11T18:07:00.415Z] 18:07:00     INFO -  DEBUG: Adding blocker PlacesUtils read-only connection closing as part of Places shutdown for phase Places Connection shutdown
[task 2022-02-11T18:07:00.415Z] 18:07:00     INFO -  DEBUG: Adding blocker PlacesUtils read-only connection must be closed before Sqlite.jsm for phase Sqlite.jsm: wait until all clients have completed their task
[task 2022-02-11T18:07:00.420Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: Bookmarks.jsm: fetchBookmarksByURL (11) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.421Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: PlacesUtils.keywords.insert (8) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.422Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: PlacesUtils.keywords.insert (12) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.422Z] 18:07:00     INFO -  DEBUG: Adding blocker Transaction (13) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.440Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: Bookmarks.jsm: fetchBookmarksByURL (14) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.441Z] 18:07:00     INFO -  DEBUG: Completed blocker Transaction (13) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.442Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: Bookmarks.jsm: fetchBookmarksByURL (14) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.444Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: PlacesUtils.keywords.insert (12) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.446Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: Bookmarks.jsm: fetchBookmark (15) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.480Z] 18:07:00     INFO -  [CodeCoverage] Setting handlers for process 22893.
[task 2022-02-11T18:07:00.613Z] 18:07:00     INFO -  DEBUG: Adding blocker Search service: shutting down for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-11T18:07:00.652Z] 18:07:00     INFO -  1644602820651	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2022-02-11T18:07:00.652Z] 18:07:00     INFO -  1644602820651	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2022-02-11T18:07:00.674Z] 18:07:00     INFO -  1644602820674	Marionette	TRACE	All scripts recorded.
[task 2022-02-11T18:07:00.678Z] 18:07:00     INFO -  1644602820677	Marionette	INFO	Listening on port 2828
[task 2022-02-11T18:07:00.678Z] 18:07:00     INFO -  1644602820678	Marionette	DEBUG	Marionette is listening
[task 2022-02-11T18:07:00.688Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: Bookmarks.jsm: fetchBookmark (15) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.688Z] 18:07:00     INFO -  DEBUG: Adding blocker Transaction (16) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.688Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: Bookmarks.jsm: insertBookmarkTree (17) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.726Z] 18:07:00     INFO -  DEBUG: Adding blocker DownloadAutoSaveView: writing data for phase profile-before-change
[task 2022-02-11T18:07:00.751Z] 18:07:00     INFO -  1644602820751	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:49906
[task 2022-02-11T18:07:00.756Z] 18:07:00     INFO -  1644602820755	Marionette	DEBUG	Closed connection 0
[task 2022-02-11T18:07:00.756Z] 18:07:00     INFO -  1644602820755	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:49908
[task 2022-02-11T18:07:00.758Z] 18:07:00     INFO -  DEBUG: Adding blocker ScriptPreloader: Saving bytecode cache for phase xpcom-will-shutdown
[task 2022-02-11T18:07:00.770Z] 18:07:00     INFO -  1644602820770	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2022-02-11T18:07:00.790Z] 18:07:00     INFO -  1644602820790	RemoteAgent	TRACE	[19] Document already finished loading: about:blank
[task 2022-02-11T18:07:00.799Z] 18:07:00     INFO -  1644602820798	Marionette	DEBUG	1 <- [1,1,null,{"sessionId":"351f3bb3-5b9b-436f-b935-ce79b5b1dc30","capabilities":{"browserName":"firefox","browserVersion":"99.0a ... x.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2022-02-11T18:07:00.802Z] 18:07:00     INFO -  DEBUG: Completed blocker Transaction (16) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.802Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: Bookmarks.jsm: insertBookmarkTree (17) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.803Z] 18:07:00     INFO -  DEBUG: Adding blocker places.sqlite#0: GuidHelper.getItemId (18) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.806Z] 18:07:00     INFO -  1644602820805	Marionette	DEBUG	1 -> [0,2,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-02-11T18:07:00.807Z] 18:07:00     INFO -  1644602820806	Marionette	DEBUG	1 <- [1,2,null,{"value":null}]
[task 2022-02-11T18:07:00.808Z] 18:07:00     INFO -  1644602820808	Marionette	DEBUG	1 -> [0,3,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-02-11T18:07:00.809Z] 18:07:00     INFO -  1644602820808	Marionette	DEBUG	1 <- [1,3,null,{"value":null}]
[task 2022-02-11T18:07:00.811Z] 18:07:00     INFO -  1644602820810	Marionette	DEBUG	1 -> [0,4,"WebDriver:ExecuteScript",{"script":"window.global = {};\n          global.LoginInfo = Components.Constructor(\"@mozilla ... dbox":"firefox-refresh","line":550,"filename":"tests/browser/components/migration/tests/marionette/test_refresh_firefox.py"}]
[task 2022-02-11T18:07:00.818Z] 18:07:00     INFO -  1644602820817	Marionette	TRACE	[7] MarionetteCommands actor created for window id 2
[task 2022-02-11T18:07:00.827Z] 18:07:00     INFO -  DEBUG: Completed blocker places.sqlite#0: GuidHelper.getItemId (18) for phase places.sqlite#0: waiting for clients
[task 2022-02-11T18:07:00.850Z] 18:07:00     INFO -  1644602820849	Marionette	DEBUG	1 <- [1,4,null,{"value":null}]
[task 2022-02-11T18:07:00.853Z] 18:07:00     INFO -  1644602820852	Marionette	DEBUG	1 -> [0,5,"WebDriver:ExecuteScript",{"script":"try {\n            global.formAutofillStorage = Cu.import(\"resource://formautofill ... dbox":"firefox-refresh","line":550,"filename":"tests/browser/components/migration/tests/marionette/test_refresh_firefox.py"}]
[task 2022-02-11T18:07:00.857Z] 18:07:00     INFO -  Missing chrome or resource URL: resource://formautofill/FormAutofillStorage.jsm
[task 2022-02-11T18:07:00.859Z] 18:07:00     INFO -  1644602820858	Marionette	DEBUG	1 <- [1,5,null,{"value":false}]
[task 2022-02-11T18:07:00.875Z] 18:07:00     INFO -  1644602820874	Marionette	DEBUG	1 -> [0,6,"WebDriver:ExecuteScript",{"script":"let name = arguments[0];\n                  let profile = global.profSvc.getProfile ... dbox":"firefox-refresh","line":550,"filename":"tests/browser/components/migration/tests/marionette/test_refresh_firefox.py"}]
[task 2022-02-11T18:07:00.879Z] 18:07:00     INFO -  1644602820878	Marionette	DEBUG	1 <- [1,6,null,{"value":null}]
[task 2022-02-11T18:07:00.887Z] 18:07:00     INFO -  1644602820886	Marionette	DEBUG	1 -> [0,7,"WebDriver:DeleteSession",{}]
[task 2022-02-11T18:07:00.890Z] 18:07:00     INFO -  1644602820889	Marionette	DEBUG	1 <- [1,7,null,{"value":null}]
[task 2022-02-11T18:07:00.890Z] 18:07:00     INFO -  1644602820890	Marionette	DEBUG	Closed connection 1

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.