Perma Linux CCov WebRender opt [tier 2] /webdriver/tests/bidi/browsing_context/navigate/navigate.py | test_payload - AssertionError: assert 'about:blank' == 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cme
Categories
(Remote Protocol :: Marionette, defect, P5)
Tracking
(firefox104 fixed)
| Tracking | Status | |
|---|---|---|
| firefox104 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: jdescottes)
References
(Regression)
Details
(Keywords: assertion, intermittent-failure, regression)
Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=383409805&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/WJoTIt5OR06BuiGcvrmLOA/runs/0/artifacts/public/logs/live_backing.log
[task 2022-07-05T16:58:17.368Z] 16:58:17 INFO - TEST-START | /webdriver/tests/bidi/browsing_context/navigate/navigate.py
[task 2022-07-05T16:58:17.368Z] 16:58:17 INFO - STDOUT: ============================= 20 passed in 12.90s ==============================
[task 2022-07-05T16:58:17.430Z] 16:58:17 INFO - STDOUT: ============================= test session starts ==============================
[task 2022-07-05T16:58:17.431Z] 16:58:17 INFO - STDOUT: platform linux -- Python 3.6.9, pytest-7.0.1, pluggy-unknown -- /builds/worker/workspace/build/venv/bin/python
[task 2022-07-05T16:58:17.433Z] 16:58:17 INFO - STDOUT: rootdir: /builds/worker/workspace/build
[task 2022-07-05T16:58:17.434Z] 16:58:17 INFO - STDOUT: plugins: asyncio-0.14.0
[task 2022-07-05T16:58:17.434Z] 16:58:17 INFO - STDOUT: collecting ...
[task 2022-07-05T16:58:17.443Z] 16:58:17 INFO - STDOUT: collected 3 items
[task 2022-07-05T16:58:17.444Z] 16:58:17 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/browsing_context/navigate/navigate.py::test_payload
[task 2022-07-05T16:58:17.446Z] 16:58:17 INFO - PID 6662 | 1657040297444 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmpfn_25r90.mozrunner"], "binary": "/builds/worker/workspace/build/application/firefox/firefox"}, "webSocketUrl": true}}}
[task 2022-07-05T16:58:17.446Z] 16:58:17 INFO - PID 6662 | 1657040297444 geckodriver::capabilities DEBUG Trying to read firefox version from ini files
[task 2022-07-05T16:58:17.447Z] 16:58:17 INFO - PID 6662 | 1657040297445 geckodriver::capabilities DEBUG Found version 104.0a1
[task 2022-07-05T16:58:17.448Z] 16:58:17 INFO - PID 6662 | 1657040297445 geckodriver::browser DEBUG Backing up prefs to "/tmp/tmpfn_25r90.mozrunner/user.geckodriver_backup_2"
[task 2022-07-05T16:58:17.452Z] 16:58:17 INFO - PID 6662 | 1657040297451 mozrunner::runner INFO Running command: "/builds/worker/workspace/build/application/firefox/firefox" "--marionette" "--profile" "/tmp/tmpfn_25r90.mozrunner" "--remote-debugging-port" "9222" "--remote-allow-hosts" "localhost" "-no-remote"
[task 2022-07-05T16:58:17.453Z] 16:58:17 INFO - PID 6662 | 1657040297451 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1
[task 2022-07-05T16:58:17.454Z] 16:58:17 INFO - PID 6662 | 1657040297451 geckodriver::browser TRACE Failed to open /tmp/tmpfn_25r90.mozrunner/MarionetteActivePort
[task 2022-07-05T16:58:17.454Z] 16:58:17 INFO - PID 6662 | 1657040297451 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-07-05T16:58:17.513Z] 16:58:17 INFO - PID 6662 | [CodeCoverage] Setting handlers for process 7135.
[task 2022-07-05T16:58:17.514Z] 16:58:17 INFO - PID 6662 | *** You are running in headless mode.
[task 2022-07-05T16:58:17.553Z] 16:58:17 INFO - PID 6662 | 1657040297551 geckodriver::browser TRACE Failed to open /tmp/tmpfn_25r90.mozrunner/MarionetteActivePort
[task 2022-07-05T16:58:17.553Z] 16:58:17 INFO - PID 6662 | 1657040297551 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-07-05T16:58:17.653Z] 16:58:17 INFO - PID 6662 | 1657040297652 geckodriver::browser TRACE Failed to open /tmp/tmpfn_25r90.mozrunner/MarionetteActivePort
[task 2022-07-05T16:58:17.654Z] 16:58:17 INFO - PID 6662 | 1657040297652 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-07-05T16:58:17.750Z] 16:58:17 INFO - PID 6662 | 1657040297749 RemoteAgent DEBUG WebDriver BiDi enabled
[task 2022-07-05T16:58:17.752Z] 16:58:17 INFO - PID 6662 | 1657040297749 RemoteAgent DEBUG CDP enabled
[task 2022-07-05T16:58:17.753Z] 16:58:17 INFO - PID 6662 | 1657040297750 Marionette INFO Marionette enabled
[task 2022-07-05T16:58:17.754Z] 16:58:17 INFO - PID 6662 | 1657040297751 Marionette TRACE Received observer notification final-ui-startup
[task 2022-07-05T16:58:17.756Z] 16:58:17 INFO - PID 6662 | 1657040297752 geckodriver::browser TRACE Failed to open /tmp/tmpfn_25r90.mozrunner/MarionetteActivePort
[task 2022-07-05T16:58:17.757Z] 16:58:17 INFO - PID 6662 | 1657040297752 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-07-05T16:58:17.757Z] 16:58:17 INFO - PID 6662 | 1657040297753 Marionette INFO Listening on port 43699
[task 2022-07-05T16:58:17.758Z] 16:58:17 INFO - PID 6662 | 1657040297753 Marionette DEBUG Marionette is listening
[task 2022-07-05T16:58:17.759Z] 16:58:17 INFO - PID 6662 | 1657040297754 RemoteAgent TRACE Received observer notification final-ui-startup
[task 2022-07-05T16:58:17.760Z] 16:58:17 INFO - PID 6662 | WebDriver BiDi listening on ws://localhost:9222
[task 2022-07-05T16:58:17.799Z] 16:58:17 INFO - PID 6662 | 1657040297798 CDP DEBUG Waiting for initial application window
[task 2022-07-05T16:58:17.853Z] 16:58:17 INFO - PID 6662 | Read port: 43699
[task 2022-07-05T16:58:17.950Z] 16:58:17 INFO - PID 6662 | 1657040297949 Marionette DEBUG Accepted connection 0 from 127.0.0.1:38030
[task 2022-07-05T16:58:17.969Z] 16:58:17 INFO - PID 6662 | 1657040297968 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:43699.
[task 2022-07-05T16:58:18.006Z] 16:58:18 INFO - PID 6662 | 1657040298004 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{"webSocketUrl":true}]
[task 2022-07-05T16:58:18.009Z] 16:58:18 INFO - PID 6662 | 1657040298008 WebDriver BiDi DEBUG Waiting for initial application window
[task 2022-07-05T16:58:18.360Z] 16:58:18 INFO - PID 6662 | [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2022-07-05T16:58:18.537Z] 16:58:18 INFO - PID 6662 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpfn_25r90.mozrunner/search.json.mozlz4", (void 0)))
[task 2022-07-05T16:58:18.608Z] 16:58:18 INFO - PID 6662 | console.error: SearchEngineSelector: "Received empty search configuration!"
[task 2022-07-05T16:58:18.708Z] 16:58:18 INFO - PID 6662 | console.error: SearchEngineSelector: "Received empty search configuration!"
[task 2022-07-05T16:58:18.709Z] 16:58:18 INFO - PID 6662 | console.error: SearchService: "#init: failure initializing search:" ({})
[task 2022-07-05T16:58:18.713Z] 16:58:18 INFO - PID 6662 | JavaScript error: , line 0: uncaught exception: 2147549183
[task 2022-07-05T16:58:18.714Z] 16:58:18 INFO - PID 6662 | JavaScript error: , line 0: uncaught exception: 2147549183
[task 2022-07-05T16:58:18.715Z] 16:58:18 INFO - PID 6662 | JavaScript error: , line 0: uncaught exception: 2147549183
[task 2022-07-05T16:58:18.716Z] 16:58:18 INFO - PID 6662 | JavaScript error: resource://gre/modules/SearchService.jsm, line 1205: NS_ERROR_UNEXPECTED: SearchService previously failed to initialize
[task 2022-07-05T16:58:18.717Z] 16:58:18 INFO - PID 6662 | JavaScript error: , line 0: uncaught exception: 2147549183
[task 2022-07-05T16:58:18.819Z] 16:58:18 INFO - PID 6662 | [CodeCoverage] Setting handlers for process 7193.
<...>
[task 2022-07-05T16:58:26.058Z] 16:58:26 INFO - PID 6662 | [Parent 7135, Main Thread] WARNING: ContentParent: id=7f98f60ea400 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3586
[task 2022-07-05T16:58:26.058Z] 16:58:26 INFO - PID 6662 | [Parent 7135, Main Thread] WARNING: ContentParent: id=7f98f60ea400 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1790
[task 2022-07-05T16:58:26.061Z] 16:58:26 INFO - PID 6662 | [Parent 7135, Main Thread] WARNING: ContentParent: id=7f98ec143200 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3586
[task 2022-07-05T16:58:26.061Z] 16:58:26 INFO - PID 6662 | [Parent 7135, Main Thread] WARNING: ContentParent: id=7f98ec143200 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1790
[task 2022-07-05T16:58:26.097Z] 16:58:26 INFO - PID 6662 | [Parent 7135, Main Thread] WARNING: ContentParent: id=7f98f60ea400 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1825
[task 2022-07-05T16:58:26.097Z] 16:58:26 INFO - PID 6662 | [Parent 7135, Main Thread] WARNING: ContentParent: id=7f98f60ea400 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3688
[task 2022-07-05T16:58:26.102Z] 16:58:26 INFO - PID 6662 | [Parent 7135, Main Thread] WARNING: ContentParent: id=7f98ec143200 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1825
[task 2022-07-05T16:58:26.102Z] 16:58:26 INFO - PID 6662 | [Parent 7135, Main Thread] WARNING: ContentParent: id=7f98ec143200 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3688
[task 2022-07-05T16:58:28.094Z] 16:58:28 INFO - PID 6662 | 1657040308093 geckodriver::browser DEBUG Browser process stopped: exit status: 0
[task 2022-07-05T16:58:28.095Z] 16:58:28 INFO - PID 6662 | 1657040308093 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-07-05T16:58:28.098Z] 16:58:28 INFO - STDOUT: =================================== FAILURES ===================================
[task 2022-07-05T16:58:28.101Z] 16:58:28 INFO - STDOUT: _________________________________ test_payload _________________________________
[task 2022-07-05T16:58:28.102Z] 16:58:28 INFO - STDOUT: bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f16f8148e10>
[task 2022-07-05T16:58:28.102Z] 16:58:28 INFO - STDOUT: inline = <function inline.<locals>.inline at 0x7f16fa3e11e0>
[task 2022-07-05T16:58:28.102Z] 16:58:28 INFO - STDOUT: new_tab = {'context': 'f5ebbd71-4eb9-44df-8597-a43f462af08a'}
[task 2022-07-05T16:58:28.102Z] 16:58:28 INFO - STDOUT: async def test_payload(bidi_session, inline, new_tab):
[task 2022-07-05T16:58:28.102Z] 16:58:28 INFO - STDOUT: url = inline("<div>foo</div>")
[task 2022-07-05T16:58:28.103Z] 16:58:28 INFO - STDOUT: result = await bidi_session.browsing_context.navigate(
[task 2022-07-05T16:58:28.103Z] 16:58:28 INFO - STDOUT: context=new_tab["context"], url=url
[task 2022-07-05T16:58:28.104Z] 16:58:28 INFO - STDOUT: )
[task 2022-07-05T16:58:28.108Z] 16:58:28 INFO -
[task 2022-07-05T16:58:28.108Z] 16:58:28 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/browsing_context/navigate/navigate.py | test_payload - AssertionError: assert 'about:blank' == 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cdiv%3Efoo%3C%2Fdiv%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2022-07-05T16:58:28.108Z] 16:58:28 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f16f8148e10>
[task 2022-07-05T16:58:28.108Z] 16:58:28 INFO - inline = <function inline.<locals>.inline at 0x7f16fa3e11e0>
[task 2022-07-05T16:58:28.108Z] 16:58:28 INFO - new_tab = {'context': 'f5ebbd71-4eb9-44df-8597-a43f462af08a'}
[task 2022-07-05T16:58:28.108Z] 16:58:28 INFO -
[task 2022-07-05T16:58:28.108Z] 16:58:28 INFO - async def test_payload(bidi_session, inline, new_tab):
[task 2022-07-05T16:58:28.108Z] 16:58:28 INFO - url = inline("<div>foo</div>")
[task 2022-07-05T16:58:28.108Z] 16:58:28 INFO - result = await bidi_session.browsing_context.navigate(
[task 2022-07-05T16:58:28.109Z] 16:58:28 INFO - context=new_tab["context"], url=url
[task 2022-07-05T16:58:28.109Z] 16:58:28 INFO - )
[task 2022-07-05T16:58:28.109Z] 16:58:28 INFO -
[task 2022-07-05T16:58:28.109Z] 16:58:28 INFO - assert "navigation" in result
[task 2022-07-05T16:58:28.109Z] 16:58:28 INFO - > assert result["url"] == url
[task 2022-07-05T16:58:28.109Z] 16:58:28 INFO - E AssertionError: assert 'about:blank' == 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cdiv%3Efoo%3C%2Fdiv%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2022-07-05T16:58:28.109Z] 16:58:28 INFO - E - http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cdiv%3Efoo%3C%2Fdiv%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-07-05T16:58:28.109Z] 16:58:28 INFO - E + about:blank
[task 2022-07-05T16:58:28.109Z] 16:58:28 INFO -
[task 2022-07-05T16:58:28.109Z] 16:58:28 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f16f8148e10>
[task 2022-07-05T16:58:28.109Z] 16:58:28 INFO - inline = <function inline.<locals>.inline at 0x7f16fa3e11e0>
[task 2022-07-05T16:58:28.109Z] 16:58:28 INFO - new_tab = {'context': 'f5ebbd71-4eb9-44df-8597-a43f462af08a'}
[task 2022-07-05T16:58:28.110Z] 16:58:28 INFO - result = {'navigation': None, 'url': 'about:blank'}
[task 2022-07-05T16:58:28.110Z] 16:58:28 INFO - url = 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cdiv%3Efoo%3C%2Fdiv%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2022-07-05T16:58:28.110Z] 16:58:28 INFO -
[task 2022-07-05T16:58:28.110Z] 16:58:28 INFO - tests/web-platform/tests/webdriver/tests/bidi/browsing_context/navigate/navigate.py:17: AssertionError
[task 2022-07-05T16:58:28.111Z] 16:58:28 INFO - ..
[task 2022-07-05T16:58:28.111Z] 16:58:28 INFO - TEST-OK | /webdriver/tests/bidi/browsing_context/navigate/navigate.py | took 10739ms
|
||
Comment 1•3 years ago
|
||
Hello Julian, could you take a look at this failure and check if Bug 1777936 has any impact on it? We suspect it's caused by the recent wptsync, but could it be the other one too? Thank you!
|
Assignee | |
Comment 2•3 years ago
•
|
||
I think it's not related to Bug 1777936, the change done in this bug does not impact the navigate command at all, which is the one tested in the failing test.
Regarding the sync, we were expecting failures from https://bugzilla.mozilla.org/show_bug.cgi?id=1777173, but not on this test. And for now I am not sure if they are related.
It's odd that it's a permafail, because from the logs it looks like an existing intermittent, where we miss the navigation from about:blank on slow platforms. See all bugs blocked on https://bugzilla.mozilla.org/show_bug.cgi?id=1767295
My only explanation here would be that the change on the new_tab fixture which landed for the sync at https://hg.mozilla.org/mozilla-central/rev/e3511a0ec6d40b417d8101f8da86cc0486317c05#l8.12 slightly changes the timings and makes this permafail on ccov.
I will try to revert that change to confirm. The correct solution should be to fix Bug 1767295 and have a more flexible timeout on slow platforms.
Keeping the ni? will report once I have more data/
Edit: couple try pushes in progress: https://treeherder.mozilla.org/jobs?repo=try&author=jdescottes%40mozilla.com&fromchange=2ad48f375e37c6e8e2b180034ad464b49827845c&tochange=e963e5232373508bb0e6aa9a686f59671dbcd140
|
|
Assignee | |
Comment 3•3 years ago
|
||
Extending the timeout seems to fix the issue, but interesting thing to note is that the problematic navigation here is not the one from the test itself. The problem actually comes from the initial tab created with browsingContext.create. Which makes more sense, because that's exactly what the sync modified.
This test basically does two things:
- create a tab on about:blank
- navigate to an inline url
When the test fails, we don't detect the initial navigation for about:blank, we resolve too early.
Then when we ask for a navigation, we still have the initial about:blank navigation which is about to be completed, and we resolve for this one incorrectly.
Logs of a successful run:
[task 2022-07-05T21:06:20.467Z] 21:06:20 INFO - PID 4383 | 1657055180466 WebDriver BiDi DEBUG d76752c8-c0fe-4315-97d2-8a825e88b18d -> {"id":1,"method":"browsingContext.create","params":{"type":"tab"}}
[task 2022-07-05T21:06:20.477Z] 21:06:20 INFO - PID 4383 | 1657055180476 RemoteAgent TRACE Registered MessageHandlerFrame actors
[task 2022-07-05T21:06:20.479Z] 21:06:20 INFO - PID 4383 | 1657055180478 RemoteAgent TRACE Created MessageHandler ROOT for session d76752c8-c0fe-4315-97d2-8a825e88b18d
[task 2022-07-05T21:06:20.485Z] 21:06:20 INFO - PID 4383 | 1657055180484 RemoteAgent TRACE Received command browsingContext.create for destination ROOT
[task 2022-07-05T21:06:20.486Z] 21:06:20 INFO - PID 4383 | 1657055180484 RemoteAgent TRACE Module root/browsingContext.jsm found for ROOT
[task 2022-07-05T21:06:21.056Z] 21:06:21 INFO - PID 4383 | [CodeCoverage] Setting handlers for process 7557.
[task 2022-07-05T21:06:21.137Z] 21:06:21 INFO - PID 4383 | 1657055181136 RemoteAgent TRACE [27] ProgressListener state=start: about:blank
[task 2022-07-05T21:06:21.199Z] 21:06:21 INFO - PID 4383 | 1657055181198 RemoteAgent TRACE [27] ProgressListener state=stop: about:blank
[task 2022-07-05T21:06:21.204Z] 21:06:21 INFO - PID 4383 | 1657055181202 WebDriver BiDi DEBUG d76752c8-c0fe-4315-97d2-8a825e88b18d <- {"id":1,"result":{"context":"b2ec4364-7500-4f2b-b55e-01f5a7966923"}}
Logs of a failing run:
[task 2022-07-05T17:30:08.052Z] 17:30:08 INFO - PID 4628 | 1657042208050 WebDriver BiDi DEBUG a78e849d-e4ff-4ae1-9946-a0130485ae9b -> {"id":1,"method":"browsingContext.create","params":{"type":"tab"}}
[task 2022-07-05T17:30:08.064Z] 17:30:08 INFO - PID 4628 | 1657042208063 RemoteAgent TRACE Registered MessageHandlerFrame actors
[task 2022-07-05T17:30:08.067Z] 17:30:08 INFO - PID 4628 | 1657042208066 RemoteAgent TRACE Created MessageHandler ROOT for session a78e849d-e4ff-4ae1-9946-a0130485ae9b
[task 2022-07-05T17:30:08.075Z] 17:30:08 INFO - PID 4628 | 1657042208073 RemoteAgent TRACE Received command browsingContext.create for destination ROOT
[task 2022-07-05T17:30:08.077Z] 17:30:08 INFO - PID 4628 | 1657042208076 RemoteAgent TRACE Module root/browsingContext.jsm found for ROOT
[task 2022-07-05T17:30:08.302Z] 17:30:08 INFO - PID 4628 | 1657042208300 RemoteAgent TRACE [27] No navigation detected: about:blank
[task 2022-07-05T17:30:08.303Z] 17:30:08 INFO - PID 4628 | 1657042208301 WebDriver BiDi DEBUG a78e849d-e4ff-4ae1-9946-a0130485ae9b <- {"id":1,"result":{"context":"390ebdf1-7e09-4685-9742-7347cf84c55a"}}
Note the [27] No navigation detected: about:blank.
So I will block on Bug 1767295, and I confirm this was regressed by the sync, precisely by https://hg.mozilla.org/mozilla-central/rev/e3511a0ec6d40b417d8101f8da86cc0486317c05
|
|
Assignee | |
Comment 4•3 years ago
|
||
Also interesting to note that the initial navigation takes more than 600ms to kick in, with a [CodeCoverage] Setting handlers for process 7557. in the middle. This explains why our 200ms unload timer is not enough here.
|
|
Assignee | |
Comment 5•3 years ago
|
||
Summary of the situation.
We have first this perma-failure to address. It is easily solved by addressing Bug 1767295, ie increasing the unloadTimer on slow platforms. However doing that still leaves us with a higher than usual rate of intermittent failures. See for instance https://treeherder.mozilla.org/jobs?repo=try&revision=e963e5232373508bb0e6aa9a686f59671dbcd140, with around 33% of the jobs which failed, compared to https://treeherder.mozilla.org/jobs?repo=try&revision=2ad48f375e37c6e8e2b180034ad464b49827845c where only 10% failed.
So we tried to investigate why we still had an increased intermittent ratio with the new fixture. In the end there are 5 main differences between the old fixture and the new one:
- old fixture waits for "TabOpen", new fixture doesn't do this
- old fixture will focus then blur the newly selected tab, new fixture doesn't do this
- old fixture will explicitly re-focus the new tab once its opened (done separately from the focus/blur above), new fixture simply leaves the new tab as a background tab
- old fixture uses window.BrowserOpenTab, nex fixture uses tabBrowser.addTab
- old fixture opens new tabs on about:newtab, new fixture opens them on about:blank
We investigated each one of them to see which change helped here. The first four have no impact on the intermittent ratio: they don't even avoid the permafailure. When applied on top of each other + Bug 1767295, the intermittent ratio doesn't seem to drastically improve.
But the last one, using about:newtab instead of about:blank, "fixes" the regression. Of course it's not something we can use in practice because we have to open on about:blank per spec, but at least we know where to look.
Now we should decide what to do here. Waiting for "TabOpen" sounds like a reasonable thing to do in regardless of this bug, but it doesn't improve the situation at all and is already planned as part of another change: https://phabricator.services.mozilla.com/D147746. So I would leave it out. The other items are either impossible to implement (starting on about:newtab) or useless.
My initial attempt at increasing the unloadTimer was to set it at 1 second instead of 200ms. But it was probably too little, as it seems that the coverage hooks can significantly slow down the opening of new tabs. So on top of this 1s for default platforms, I tried to also increase the timeout for the initial load to 5 seconds, for ccov only, at https://treeherder.mozilla.org/jobs?repo=try&revision=af65ad0b2fee52db430bf0852af8a5309ef39f0d. After doing that, the only failure we have left is apparently https://bugzilla.mozilla.org/show_bug.cgi?id=1764661 . The failure rate still seems a bit high, but acceptable.
I also tried to increase the timeout used in that failing test, and that gives us a fully green try: https://treeherder.mozilla.org/jobs?repo=try&selectedTaskRun=GEKGfE4HRHaCQhoUD4G34A.0&revision=2426b712b7faceef771de66365dc252b6cfa273d (this is more for reference, I doubt we want to apply that).
My suggestion is to go ahead with Bug 1767295, potentially using 5 seconds for ccov (only for the initial timeout or in general).
Discussed with Julian on Elements and we want to go ahead with the increase of the unload timer. Anything that helps to get rid of the perma failure will be helpful and that bug was on our todo list anyway.
Julian, thank you for doing all the great research here!
| Comment hidden (Intermittent Failures Robot) |
|
|
Assignee | |
Comment 8•3 years ago
|
||
This one should be fixed now that Bug 1767295 landed. Let's wait for a few days to decide what to do here.
There are no more failures. We can close the bug as fixed.
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 11•2 years ago
|
||
Description
•