Closed Bug 1602686 Opened 4 years ago Closed 4 years ago

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)

All
Windows
defect

Tracking

(firefox72 unaffected, firefox73 disabled, firefox74 fixed)

RESOLVED FIXED
Firefox 74
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',

It seems that this started from Bug 1597877 after it was merged to central.
Maja can you please take a look?

Flags: needinfo?(mjzffr)
Regressed by: 1597877

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
OS: Unspecified → Windows
Hardware: Unspecified → All
Summary: Intermittent remote/test/browser/page/browser_createIsolatedWorld.js | Received Runtime context events in expected order - ["Runtime.executionContextCreated","Runtime.executionContextCreated","Runtime.executionContextDestroyed"... → Intermittent [tier2] Tv2 Win remote/test/browser/page/browser_createIsolatedWorld.js | Received Runtime context events in expected order - ["Runtime.executionContextCreated","Runtime.executionContextCreated","Runtime.executionContextDestroyed"...
Summary: Intermittent [tier2] Tv2 Win remote/test/browser/page/browser_createIsolatedWorld.js | Received Runtime context events in expected order - ["Runtime.executionContextCreated","Runtime.executionContextCreated","Runtime.executionContextDestroyed"... → Intermittent [tier2] Win remote/test/browser/page/browser_createIsolatedWorld.js | Received Runtime context events in expected order - ["Runtime.executionContextCreated","Runtime.executionContextCreated","Runtime.executionContextDestroyed"...
Summary: Intermittent [tier2] Win remote/test/browser/page/browser_createIsolatedWorld.js | Received Runtime context events in expected order - ["Runtime.executionContextCreated","Runtime.executionContextCreated","Runtime.executionContextDestroyed"... → Intermittent Win remote/test/browser/page/browser_createIsolatedWorld.js | Received Runtime context events in expected order - ["Runtime.executionContextCreated","Runtime.executionContextCreated","Runtime.executionContextDestroyed"...
Summary: Intermittent Win remote/test/browser/page/browser_createIsolatedWorld.js | Received Runtime context events in expected order - ["Runtime.executionContextCreated","Runtime.executionContextCreated","Runtime.executionContextDestroyed"... → Intermittent remote/test/browser/page/browser_createIsolatedWorld.js | Received Runtime context events in expected order - ["Runtime.executionContextCreated","Runtime.executionContextCreated","Runtime.executionContextDestroyed"...

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

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
Depends on: 1603776
Flags: needinfo?(mjzffr)

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.

Flags: needinfo?(mjzffr)
Assignee: nobody → mjzffr
Status: NEW → ASSIGNED
Flags: needinfo?(mjzffr)
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/28abd2840682
Check that navigation has completed; r=remote-protocol-reviewers,whimboo
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 74

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

Flags: needinfo?(ryanvm)

It's a testsuite which doesn't run on Beta.

Flags: needinfo?(ryanvm)
Component: CDP: Page → CDP
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: