Intermittent remote/test/browser/page/browser_createIsolatedWorld.js | Received Runtime context events in expected order - ["Runtime.executionContextCreated","Runtime.executionContextCreated","Runtime.executionContextDestroyed"...
Categories
(Remote Protocol :: CDP, defect, P5)
Tracking
(firefox72 unaffected, firefox73 disabled, firefox74 fixed)
Tracking | Status | |
---|---|---|
firefox72 | --- | unaffected |
firefox73 | --- | disabled |
firefox74 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: impossibus)
References
(Regression)
Details
(Keywords: intermittent-failure, Whiteboard: [stockwell needswork:owner])
Attachments
(1 file)
Filed by: aiakab [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=280430987&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ITl1OBaDTvOAdxVv8ostdw/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ITl1OBaDTvOAdxVv8ostdw/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1
[task 2019-12-10T06:36:00.011Z] 06:36:00 INFO - INFO - File win32-minidump_stackwalk.exe not present in local cache folder y:\tooltool-cache
[task 2019-12-10T06:36:00.011Z] 06:36:00 INFO - INFO - Attempting to fetch from 'https://tooltool.mozilla-releng.net/'...
[task 2019-12-10T06:36:01.210Z] 06:36:01 INFO - INFO - File win32-minidump_stackwalk.exe fetched from https://tooltool.mozilla-releng.net/ as Z:\task_1575958544\build\tmpdliekf
[task 2019-12-10T06:36:01.230Z] 06:36:01 INFO - INFO - File integrity verified, renaming tmpdliekf to win32-minidump_stackwalk.exe
[task 2019-12-10T06:36:01.230Z] 06:36:01 INFO - INFO - Updating local cache y:\tooltool-cache...
[task 2019-12-10T06:36:01.250Z] 06:36:01 INFO - INFO - Local cache y:\tooltool-cache updated with win32-minidump_stackwalk.exe
[task 2019-12-10T06:36:01.309Z] 06:36:01 INFO - Return code: 0
[task 2019-12-10T06:36:01.309Z] 06:36:01 INFO - Chmoding Z:\task_1575958544\build\win32-minidump_stackwalk.exe to 0755
[task 2019-12-10T06:36:01.310Z] 06:36:01 INFO - ENV: MOZ_NODE_PATH is now Z:/task_1575958544/fetches\node/node.exe
[task 2019-12-10T06:36:01.310Z] 06:36:01 INFO - ENV: STYLO_THREADS is now 4
[task 2019-12-10T06:36:01.310Z] 06:36:01 INFO - ENV: RUST_BACKTRACE is now full
[task 2019-12-10T06:36:01.310Z] 06:36:01 INFO - ENV: TEST_SUITE is now mochitest-remote
[task 2019-12-10T06:36:01.310Z] 06:36:01 INFO - ENV: MOZ_UPLOAD_DIR is now Z:\task_1575958544\build\blobber_upload_dir
[task 2019-12-10T06:36:01.310Z] 06:36:01 INFO - ENV: MINIDUMP_STACKWALK is now Z:\task_1575958544\build\win32-minidump_stackwalk.exe
[task 2019-12-10T06:36:01.310Z] 06:36:01 INFO - ENV: MINIDUMP_SAVE_PATH is now Z:\task_1575958544\build\blobber_upload_dir
[task 2019-12-10T06:36:01.311Z] 06:36:01 INFO - Per-test file(s) for 'mochitest-remote': [u'remote/test/browser/page/browser_runtimeEvents.js', u'remote/test/browser/page/browser_createIsolatedWorld.js']
[task 2019-12-10T06:36:01.311Z] 06:36:01 INFO - Running command: ['Z:\task_1575958544\build\venv\Scripts\python', '-u', 'Z:\task_1575958544\build\tests\mochitest\runtests.py', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--appname=Z:\task_1575958544\build\application\firefox\firefox.exe', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=Z:\task_1575958544\build\symbols', '--certificate-path=tests/certs', '--quiet', '--log-raw=Z:\task_1575958544\build\blobber_upload_dir\mochitest-remote_raw.log', '--log-errorsummary=Z:\task_1575958544\build\blobber_upload_dir\mochitest-remote_errorsummary.log', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--log-raw=-', '--flavor=browser', '--subsuite=remote', '--verify-max-time=900', '--verify', u'remote/test/browser/page/browser_runtimeEvents.js'] in Z:\task_1575958544\build
[task 2019-12-10T06:36:01.311Z] 06:36:01 INFO - Copy/paste: Z:\task_1575958544\build\venv\Scripts\python -u Z:\task_1575958544\build\tests\mochitest\runtests.py --setpref=media.peerconnection.mtransport_process=false --setpref=network.process.enabled=false --appname=Z:\task_1575958544\build\application\firefox\firefox.exe --utility-path=tests/bin --extra-profile-file=tests/bin/plugins --symbols-path=Z:\task_1575958544\build\symbols --certificate-path=tests/certs --quiet --log-raw=Z:\task_1575958544\build\blobber_upload_dir\mochitest-remote_raw.log --log-errorsummary=Z:\task_1575958544\build\blobber_upload_dir\mochitest-remote_errorsummary.log --screenshot-on-fail --cleanup-crashes --marionette-startup-timeout=180 --log-raw=- --flavor=browser --subsuite=remote --verify-max-time=900 --verify remote/test/browser/page/browser_runtimeEvents.js
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - Using env: {'ALLUSERSPROFILE': 'C:\ProgramData',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'APPDATA': 'Z:\task_1575958544\AppData\Roaming',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'COMMONPROGRAMFILES': 'C:\Program Files\Common Files',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'COMPUTERNAME': 'I-0AE6AF78B6C76',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'COMSPEC': 'C:\windows\system32\cmd.exe',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'DCLOCATION': 'SCL3',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'DNSSUFFIX': 'use1.mozilla.com',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'EXTRA_MOZHARNESS_CONFIG': '{"test_packages_url": "https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/CbS8JGfVT5atRtC_16qEsw/artifacts/public/build/target.test_packages.json", "installer_url": "https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/CbS8JGfVT5atRtC_16qEsw/artifacts/public/build/target.zip"}',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'FP_NO_HOST_CHECK': 'NO',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'GECKO_HEAD_REPOSITORY': 'https://hg.mozilla.org/mozilla-central',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'GECKO_HEAD_REV': '8b6d1b8364bdf19fc0f9bda914cf07deff63a5f5',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'HOMEDRIVE': 'C:',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'HOMEPATH': '\Users\task_1575958544',
[task 2019-12-10T06:36:01.315Z] 06:36:01 INFO - 'KTS_HOME': 'C:\Program Files\KTS',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'KTS_VERSION': '1.19c',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'LOCALAPPDATA': 'Z:\task_1575958544\AppData\Local',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'LOGONSERVER': '\\I-0AE6AF78B6C76',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'MINIDUMP_SAVE_PATH': 'Z:\task_1575958544\build\blobber_upload_dir',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'MINIDUMP_STACKWALK': 'Z:\task_1575958544\build\win32-minidump_stackwalk.exe',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'MOZILLABUILD': 'C:\mozilla-build',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'MOZ_AUTOMATION': '1',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'MOZ_FETCHES': '[{"artifact": "public/build/node.tar.bz2", "extract": true, "task": "VwFFkPyHTxWXgarYESI3Sw"}]',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'MOZ_FETCHES_DIR': 'Z:/task_1575958544/fetches',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'MOZ_NODE_PATH': 'Z:/task_1575958544/fetches\node/node.exe',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'MOZ_SCM_LEVEL': '3',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'MOZ_UPLOAD_DIR': 'Z:\task_1575958544\build\blobber_upload_dir',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'NUMBER_OF_PROCESSORS': '8',
[task 2019-12-10T06:36:01.316Z] 06:36:01 INFO - 'OS': 'Windows_NT',
Comment 1•5 years ago
|
||
It seems that this started from Bug 1597877 after it was merged to central.
Maja can you please take a look?
Comment 2•5 years ago
|
||
The above log excerpt isn't useful at all. So here the correct one:
[task 2019-12-10T06:41:40.901Z] 06:41:40 INFO - Navigating...
[task 2019-12-10T06:41:40.901Z] 06:41:40 INFO - Received Runtime.executionContextCreated for id 1
[task 2019-12-10T06:41:40.901Z] 06:41:40 INFO - Received Runtime.executionContextCreated for id 2
[task 2019-12-10T06:41:40.901Z] 06:41:40 INFO - Received Runtime.executionContextDestroyed
[task 2019-12-10T06:41:40.901Z] 06:41:40 INFO - Received Runtime.executionContextDestroyed
[task 2019-12-10T06:41:40.901Z] 06:41:40 INFO - Received Runtime.executionContextCreated for id 3
[task 2019-12-10T06:41:40.902Z] 06:41:40 INFO - Buffered messages finished
[task 2019-12-10T06:41:40.902Z] 06:41:40 INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/page/browser_createIsolatedWorld.js | Received Runtime context events in expected order - ["Runtime.executionContextCreated","Runtime.executionContextCreated","Runtime.executionContextDestroyed","Runtime.executionContextDestroyed","Runtime.executionContextCreated"] deepEqual ["Runtime.executionContextCreated","Runtime.executionContextDestroyed","Runtime.executionContextCreated","Runtime.executionContextCreated"] - JS frame :: chrome://mochitests/content/browser/remote/test/browser/page/browser_createIsolatedWorld.js :: assertEventOrder :: line 242
[task 2019-12-10T06:41:40.902Z] 06:41:40 INFO - Stack trace:
[task 2019-12-10T06:41:40.902Z] 06:41:40 INFO - chrome://mochitests/content/browser/remote/test/browser/page/browser_createIsolatedWorld.js:assertEventOrder:242
[task 2019-12-10T06:41:40.902Z] 06:41:40 INFO - chrome://mochitests/content/browser/remote/test/browser/page/browser_createIsolatedWorld.js:contextCreatedAfterNavigation:45
[task 2019-12-10T06:41:40.902Z] 06:41:40 INFO - chrome://mochitests/content/browser/remote/test/browser/head.js:this.add_task/<:42
[task 2019-12-10T06:41:40.902Z] 06:41:40 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1062
[task 2019-12-10T06:41:40.902Z] 06:41:40 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
[task 2019-12-10T06:41:40.902Z] 06:41:40 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:919
[task 2019-12-10T06:41:40.902Z] 06:41:40 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:808
This seems to happen on Windows only.
There is also a different failure in the same test that might be related, and caused by the failure above:
[task 2019-12-10T06:41:41.205Z] 06:41:41 INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/page/browser_createIsolatedWorld.js | Uncaught exception - at chrome://mochitests/content/browser/remote/test/browser/page/browser_createIsolatedWorld.js:53 - TypeError: defaultContext is undefined
[task 2019-12-10T06:41:41.206Z] 06:41:41 INFO - Stack trace:
[task 2019-12-10T06:41:41.206Z] 06:41:41 INFO - contextCreatedAfterNavigation@chrome://mochitests/content/browser/remote/test/browser/page/browser_createIsolatedWorld.js:53:3
[task 2019-12-10T06:41:41.206Z] 06:41:41 INFO - async*this.add_task/<@chrome://mochitests/content/browser/remote/test/browser/head.js:42:15
[task 2019-12-10T06:41:41.206Z] 06:41:41 INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1062:34
[task 2019-12-10T06:41:41.206Z] 06:41:41 INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1097:11
[task 2019-12-10T06:41:41.206Z] 06:41:41 INFO - nextTest/<@chrome://mochikit/content/browser-test.js:919:14
[task 2019-12-10T06:41:41.206Z] 06:41:41 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:808:67
Updated•5 years ago
|
Comment 3•5 years ago
|
||
Started appearing on non-verify jobs as well: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=280476355&repo=mozilla-central&lineNumber=4725
Assignee | ||
Comment 4•5 years ago
|
||
Comment 5•5 years ago
|
||
Tier 1 failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=280751209&repo=autoland&lineNumber=4575
Comment 6•5 years ago
|
||
This is also failing on Linux: https://treeherder.mozilla.org/logviewer.html#?job_id=280949886&repo=mozilla-central
Comment hidden (Intermittent Failures Robot) |
Comment 8•5 years ago
|
||
As of right now there are no more failures since Dec 14th. Maybe the fix on bug 1603266 helped here and we do not have any dangling events hanging around anymore?
Maja, can you please check? Thanks
Assignee | ||
Comment 9•5 years ago
|
||
This might be due to Page.navigate
returning too early (Bug 1603776). In the flaky test, we make a call to Page.createIsolatedWorld
(see testWorldc
below) right after Page.navigate. The isolated execution context is created for the previous URL even though we should have finished navigating by then.
This test happens to catch the problem because we get an extra executionContextDestroyed
event as a result.
Log excerpt: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=281593012&repo=try&lineNumber=5741-5758
[task 2019-12-17T18:51:01.885Z] 18:51:01 INFO - Runtime notifications are enabled
[task 2019-12-17T18:51:01.885Z] 18:51:01 INFO - Navigating to data:text/html;charset=utf-8,%3C!doctype%20html%3E%0A%3Cmeta%20charset%3Dutf-8%3E%0Adefault-test-page
[task 2019-12-17T18:51:01.885Z] 18:51:01 INFO - Received Runtime.executionContextCreated for id 1
[task 2019-12-17T18:51:01.885Z] 18:51:01 INFO - origin about:blank
[task 2019-12-17T18:51:01.885Z] 18:51:01 INFO - type default
[task 2019-12-17T18:51:01.885Z] 18:51:01 INFO - name
[task 2019-12-17T18:51:01.885Z] 18:51:01 INFO - Received Runtime.executionContextCreated for id 2
[task 2019-12-17T18:51:01.885Z] 18:51:01 INFO - origin about:blank
[task 2019-12-17T18:51:01.886Z] 18:51:01 INFO - type isolated
[task 2019-12-17T18:51:01.886Z] 18:51:01 INFO - name testWorldc
[task 2019-12-17T18:51:01.886Z] 18:51:01 INFO - Received Runtime.executionContextDestroyed for 1
[task 2019-12-17T18:51:01.886Z] 18:51:01 INFO - Received Runtime.executionContextDestroyed for 2
[task 2019-12-17T18:51:01.886Z] 18:51:01 INFO - Received Runtime.executionContextCreated for id 3
[task 2019-12-17T18:51:01.886Z] 18:51:01 INFO - origin data:text/html;charset=utf-8,%3C!doctype%20html%3E%0A%3Cmeta%20charset%3Dutf-8%3E%0Adefault-test-page
[task 2019-12-17T18:51:01.886Z] 18:51:01 INFO - type default
[task 2019-12-17T18:51:01.886Z] 18:51:01 INFO - name
[task 2019-12-17T18:51:01.886Z] 18:51:01 INFO - Buffered messages finished
[task 2019-12-17T18:51:01.887Z] 18:51:01 INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/page/browser_createIsolatedWorld.js | Received Runtime context events in expected order - ["Runtime.executionContextCreated","Runtime.executionContextCreated","Runtime.executionContextDestroyed","Runtime.executionContextDestroyed","Runtime.executionContextCreated"] deepEqual ["Runtime.executionContextCreated","Runtime.executionContextDestroyed","Runtime.executionContextCreated","Runtime.executionContextCreated"] - JS frame :: chrome://mochitests/content/browser/remote/test/browser/page/browser_createIsolatedWorld.js :: assertEventOrder :: line 274
Assignee | ||
Updated•5 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 13•5 years ago
|
||
There are 26 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-01-01&endday=2020-01-08&tree=trunk&bug=1602686.
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=284090994&repo=autoland&lineNumber=6176
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 16•5 years ago
|
||
Maja, would it help to temporarily add a small delay after the page load so that we could circumvent the problem for now? Not the best solution but we should get this failure stopped.
Assignee | ||
Updated•5 years ago
|
Assignee | ||
Comment 17•5 years ago
|
||
Comment 18•5 years ago
|
||
Comment 19•5 years ago
|
||
bugherder |
Updated•5 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 21•5 years ago
|
||
status-firefox73: affected → disabled
Ryan, why did you set the status to disabled for 73? Nothing has been disabled on that branch:
https://searchfox.org/mozilla-beta/rev/eacd175b582f115727d6b04605be469f9674b8ab/remote/test/browser/page/browser.ini#12
Updated•4 years ago
|
Description
•