Closed Bug 1764615 Opened 2 years ago Closed 2 years ago

Intermittent /webdriver/tests/bidi/browsing_context/navigate/invalid.py | test_params_url_invalid_type[False] - setup error: webdriver.error.NoSuchWindowException: no such window (404): Browsing context has been discarded

Categories

(Remote Protocol :: Marionette, defect, P5)

defect

Tracking

(firefox101 fixed)

RESOLVED FIXED
101 Branch
Tracking Status
firefox101 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: jdescottes)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

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


[task 2022-04-13T17:52:17.125Z] 17:52:17     INFO - STDOUT: ERROR
[task 2022-04-13T17:52:17.126Z] 17:52:17     INFO - PID 1306 | 1649872337124	webdriver::server	DEBUG	-> DELETE /session/6d0ff10e-a38b-4af5-aa88-acc44af42b6e
[task 2022-04-13T17:52:17.126Z] 17:52:17     INFO - PID 1306 | 1649872337125	Marionette	DEBUG	0 -> [0,138,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-04-13T17:52:17.127Z] 17:52:17     INFO - PID 1306 | 1649872337125	Marionette	INFO	Stopped listening on port 37789
[task 2022-04-13T17:52:17.130Z] 17:52:17     INFO - PID 1306 | 1649872337127	WebDriver BiDi	DEBUG	Unregistered session handler: /session/6d0ff10e-a38b-4af5-aa88-acc44af42b6e
[task 2022-04-13T17:52:17.130Z] 17:52:17     INFO - PID 1306 | 1649872337127	RemoteAgent	DEBUG	WebDriverBiDiConnection 43ff8f71-7df0-405e-979f-e55e6ac160cf closed
[task 2022-04-13T17:52:17.132Z] 17:52:17     INFO - PID 1306 | 1649872337127	RemoteAgent	DEBUG	WebDriverBiDiConnection 5816693f-b759-422c-8bfb-ef5998a0d3b0 closed
[task 2022-04-13T17:52:17.132Z] 17:52:17     INFO - PID 1306 | 1649872337128	RemoteAgent	DEBUG	WebDriverBiDiConnection f6bc44d9-c254-43e9-b723-b0c43dca6cfb closed
[task 2022-04-13T17:52:17.132Z] 17:52:17     INFO - PID 1306 | 1649872337128	RemoteAgent	DEBUG	WebDriverBiDiConnection 8ffe9999-f468-4b6a-8417-406ae9973af1 closed
[task 2022-04-13T17:52:17.135Z] 17:52:17     INFO - PID 1306 | 1649872337128	RemoteAgent	DEBUG	WebDriverBiDiConnection f02032f3-ea9a-4773-80cc-b466a1ba59e5 closed
[task 2022-04-13T17:52:17.135Z] 17:52:17     INFO - PID 1306 | 1649872337128	RemoteAgent	DEBUG	WebDriverBiDiConnection 04f22e75-7066-4ef2-a674-8a172346ed1d closed
[task 2022-04-13T17:52:17.136Z] 17:52:17     INFO - PID 1306 | 1649872337128	RemoteAgent	DEBUG	WebDriverBiDiConnection be0d5a86-1192-4f95-96ae-8da98677c3f7 closed
[task 2022-04-13T17:52:17.136Z] 17:52:17     INFO - PID 1306 | 1649872337128	RemoteAgent	DEBUG	WebDriverBiDiConnection b357d851-1856-43c1-a0ac-d25109b1d961 closed
[task 2022-04-13T17:52:17.136Z] 17:52:17     INFO - PID 1306 | 1649872337128	RemoteAgent	DEBUG	WebDriverBiDiConnection 79fc0e54-eb1e-4f6c-9da2-2a1ac23f50b3 closed
[task 2022-04-13T17:52:17.136Z] 17:52:17     INFO - PID 1306 | 1649872337128	RemoteAgent	DEBUG	WebDriverBiDiConnection bed73a2f-d6f8-4235-b895-af7a97edf08a closed
[task 2022-04-13T17:52:17.140Z] 17:52:17     INFO - PID 1306 | 1649872337128	RemoteAgent	DEBUG	WebDriverBiDiConnection b9eb2506-1604-47ef-bdab-c7bd1f4a4a1e closed
[task 2022-04-13T17:52:17.140Z] 17:52:17     INFO - PID 1306 | 1649872337128	RemoteAgent	DEBUG	WebDriverBiDiConnection 10b9784d-f0d6-4531-b2e8-af2392727466 closed
[task 2022-04-13T17:52:17.140Z] 17:52:17     INFO - PID 1306 | 1649872337129	RemoteAgent	TRACE	MessageHandler ROOT for session 6d0ff10e-a38b-4af5-aa88-acc44af42b6e is being destroyed
[task 2022-04-13T17:52:17.140Z] 17:52:17     INFO - PID 1306 | 1649872337129	RemoteAgent	TRACE	Unregistered MessageHandler ROOT for session 6d0ff10e-a38b-4af5-aa88-acc44af42b6e
[task 2022-04-13T17:52:17.162Z] 17:52:17     INFO - PID 1306 | 1649872337161	Marionette	TRACE	Received observer notification quit-application
[task 2022-04-13T17:52:17.163Z] 17:52:17     INFO - PID 1306 | 1649872337161	Marionette	TRACE	Received observer notification quit-application
[task 2022-04-13T17:52:17.164Z] 17:52:17     INFO - PID 1306 | 1649872337162	Marionette	DEBUG	Marionette stopped listening
[task 2022-04-13T17:52:17.165Z] 17:52:17     INFO - PID 1306 | 1649872337164	RemoteAgent	TRACE	Received observer notification quit-application
[task 2022-04-13T17:52:17.166Z] 17:52:17     INFO - PID 1306 | 1649872337164	Marionette	DEBUG	0 <- [1,138,null,{"cause":"shutdown","forced":false}]
[task 2022-04-13T17:52:17.194Z] 17:52:17     INFO - PID 1306 | 1649872337192	RemoteAgent	DEBUG	Resetting recommended pref browser.contentblocking.features.standard
[task 2022-04-13T17:52:17.194Z] 17:52:17     INFO - PID 1306 | 1649872337192	RemoteAgent	DEBUG	Resetting recommended pref network.cookie.cookieBehavior
[task 2022-04-13T17:52:17.194Z] 17:52:17     INFO - PID 1306 | 1649872337192	webdriver::server	DEBUG	Teardown session
[task 2022-04-13T17:52:17.196Z] 17:52:17     INFO - PID 1306 | 1649872337194	Marionette	DEBUG	Closed connection 0
[task 2022-04-13T17:52:17.369Z] 17:52:17     INFO - PID 1306 | [2022-04-13T17:52:17Z ERROR xulstore::persist] removeDocument error: unavailable
[task 2022-04-13T17:52:17.394Z] 17:52:17     INFO - PID 1306 | 1649872337393	geckodriver::browser	DEBUG	Browser process stopped: exit status: 0
[task 2022-04-13T17:52:17.394Z] 17:52:17     INFO - PID 1306 | 1649872337393	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-04-13T17:52:17.407Z] 17:52:17     INFO - STDOUT: ==================================== ERRORS ====================================
[task 2022-04-13T17:52:17.414Z] 17:52:17     INFO - STDOUT: ____________ ERROR at setup of test_params_url_invalid_type[False] _____________
[task 2022-04-13T17:52:17.415Z] 17:52:17     INFO - STDOUT: args = ()
[task 2022-04-13T17:52:17.416Z] 17:52:17     INFO - STDOUT: kwargs = {'capabilities': {}, 'configuration': {'capabilities': {'moz:firefoxOptions': {'args': ['--profile', '/tmp/tmpp9vtv3pa...}, 'host': '127.0.0.1', 'port': 34186, 'webdriver': {'args': ['-vv'], 'binary': '/builds/worker/fetches/geckodriver'}}}
[task 2022-04-13T17:52:17.418Z] 17:52:17     INFO - STDOUT: request = <SubRequest 'bidi_session' for <Function test_params_url_invalid_type[False]>>
[task 2022-04-13T17:52:17.419Z] 17:52:17     INFO - STDOUT: setup = <function pytest_fixture_setup.<locals>.wrapper.<locals>.setup at 0x7f0720732c80>
[task 2022-04-13T17:52:17.420Z] 17:52:17     INFO - STDOUT: finalizer = <function pytest_fixture_setup.<locals>.wrapper.<locals>.finalizer at 0x7f0720732d08>
[task 2022-04-13T17:52:17.422Z] 17:52:17     INFO - STDOUT:     def wrapper(*args, **kwargs):
[task 2022-04-13T17:52:17.422Z] 17:52:17     INFO - STDOUT:         loop = fixture_stripper.get_and_strip_from(FixtureStripper.EVENT_LOOP, kwargs)
[task 2022-04-13T17:52:17.422Z] 17:52:17     INFO - STDOUT:         request = fixture_stripper.get_and_strip_from(FixtureStripper.REQUEST, kwargs)
[task 2022-04-13T17:52:17.423Z] 17:52:17     INFO - STDOUT:     
[task 2022-04-13T17:52:17.424Z] 17:52:17     INFO - STDOUT:         gen_obj = generator(*args, **kwargs)
[task 2022-04-13T17:52:17.424Z] 17:52:17     INFO - STDOUT:     
[task 2022-04-13T17:52:17.425Z] 17:52:17     INFO - STDOUT:         async def setup():
[task 2022-04-13T17:52:17.426Z] 17:52:17     INFO - STDOUT:             res = await gen_obj.__anext__()
[task 2022-04-13T17:52:17.427Z] 17:52:17     INFO - STDOUT:             return res
[task 2022-04-13T17:52:17.428Z] 17:52:17     INFO - STDOUT:     
[task 2022-04-13T17:52:17.432Z] 17:52:17     INFO - STDOUT:         def finalizer():
[task 2022-04-13T17:52:17.432Z] 17:52:17     INFO - STDOUT:             """Yield again, to finalize."""
[task 2022-04-13T17:52:17.432Z] 17:52:17     INFO - STDOUT:             async def async_finalizer():
[task 2022-04-13T17:52:17.432Z] 17:52:17     INFO - STDOUT:                 try:
[task 2022-04-13T17:52:17.433Z] 17:52:17     INFO - STDOUT:                     await gen_obj.__anext__()
[task 2022-04-13T17:52:17.433Z] 17:52:17     INFO - STDOUT:                 except StopAsyncIteration:
[task 2022-04-13T17:52:17.433Z] 17:52:17     INFO - STDOUT:                     pass
[task 2022-04-13T17:52:17.433Z] 17:52:17     INFO - STDOUT:                 else:
[task 2022-04-13T17:52:17.433Z] 17:52:17     INFO - STDOUT:                     msg = "Async generator fixture didn't stop."
[task 2022-04-13T17:52:17.434Z] 17:52:17     INFO - STDOUT:                     msg += "Yield only once."
[task 2022-04-13T17:52:17.434Z] 17:52:17     INFO - STDOUT:                     raise ValueError(msg)
[task 2022-04-13T17:52:17.444Z] 17:52:17     INFO - 
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/invalid.py | test_params_context_invalid_type[None] 
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/invalid.py | test_params_context_invalid_type[False] 
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/invalid.py | test_params_context_invalid_type[42] 
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/invalid.py | test_params_context_invalid_type[value3] 
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/invalid.py | test_params_context_invalid_type[value4] 
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/invalid.py | test_params_context_invalid_value[] 
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/invalid.py | test_params_context_invalid_value[somestring] 
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/invalid.py | test_params_url_invalid_type[None] 
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/bidi/browsing_context/navigate/invalid.py | test_params_url_invalid_type[False] - setup error: webdriver.error.NoSuchWindowException: no such window (404): Browsing context has been discarded
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - args = ()
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - kwargs = {'capabilities': {}, 'configuration': {'capabilities': {'moz:firefoxOptions': {'args': ['--profile', '/tmp/tmpp9vtv3pa...}, 'host': '127.0.0.1', 'port': 34186, 'webdriver': {'args': ['-vv'], 'binary': '/builds/worker/fetches/geckodriver'}}}
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - request = <SubRequest 'bidi_session' for <Function test_params_url_invalid_type[False]>>
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - setup = <function pytest_fixture_setup.<locals>.wrapper.<locals>.setup at 0x7f0720732c80>
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - finalizer = <function pytest_fixture_setup.<locals>.wrapper.<locals>.finalizer at 0x7f0720732d08>
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO - 
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO -     def wrapper(*args, **kwargs):
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO -         loop = fixture_stripper.get_and_strip_from(FixtureStripper.EVENT_LOOP, kwargs)
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO -         request = fixture_stripper.get_and_strip_from(FixtureStripper.REQUEST, kwargs)
[task 2022-04-13T17:52:17.445Z] 17:52:17     INFO -     
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -         gen_obj = generator(*args, **kwargs)
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -     
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -         async def setup():
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -             res = await gen_obj.__anext__()
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -             return res
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -     
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -         def finalizer():
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -             """Yield again, to finalize."""
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -             async def async_finalizer():
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                 try:
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                     await gen_obj.__anext__()
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                 except StopAsyncIteration:
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                     pass
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                 else:
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                     msg = "Async generator fixture didn't stop."
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                     msg += "Yield only once."
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                     raise ValueError(msg)
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -             loop.run_until_complete(async_finalizer())
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -     
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -         request.addfinalizer(finalizer)
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO - >       return loop.run_until_complete(setup())
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO - 
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO - args       = ()
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO - finalizer  = <function pytest_fixture_setup.<locals>.wrapper.<locals>.finalizer at 0x7f0720732d08>
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO - fixture_stripper = <pytest_asyncio.plugin.FixtureStripper object at 0x7f0720751fd0>
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO - gen_obj    = <async_generator object bidi_session at 0x7f0720717f50>
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO - generator  = <function bidi_session at 0x7f0743ed4ae8>
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO - kwargs     = {'capabilities': {},
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -  'configuration': {'capabilities': {'moz:firefoxOptions': {'args': ['--profile',
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                                                                     '/tmp/tmpp9vtv3pa.mozrunner'],
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                                                            'binary': '/builds/worker/workspace/build/application/firefox/firefox'}},
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                    'host': '127.0.0.1',
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                    'port': 34186,
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                    'webdriver': {'args': ['-vv'],
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO -                                  'binary': '/builds/worker/fetches/geckodriver'}}}
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO - loop       = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2022-04-13T17:52:17.446Z] 17:52:17     INFO - request    = <SubRequest 'bidi_session' for <Function test_params_url_invalid_type[False]>>
[task 2022-04-13T17:52:17.447Z] 17:52:17     INFO - setup      = <function pytest_fixture_setup.<locals>.wrapper.<locals>.setup at 0x7f0720732c80>
[task 2022-04-13T17:52:17.447Z] 17:52:17     INFO - 
[task 2022-04-13T17:52:17.447Z] 17:52:17     INFO - tests/web-platform/tests/tools/third_party/pytest-asyncio/pytest_asyncio/plugin.py:127: 
[task 2022-04-13T17:52:17.447Z] 17:52:17     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2022-04-13T17:52:17.447Z] 17:52:17     INFO - /usr/lib/python3.6/asyncio/base_events.py:484: in run_until_complete

:jdescottes, since you are the author of the regressor, bug 1763692, could you take a look?
For more information, please visit auto_nag documentation.

Flags: needinfo?(jdescottes)

This intermittent most likely comes from the new_tab fixture, because I set the new tab as the current window for the WebDriver session at:

    # Open and focus a new tab to run the test in a foreground tab.
    context_id = current_session.new_window(type_hint="tab")
    current_session.window_handle = context_id

I tried to restore the window_handle at the end of the test, which seems to fix the issue https://treeherder.mozilla.org/jobs?repo=try&revision=90dfcc0fe5ad2ca1562a75ce566a65f23bbda235

I assume we can also avoid updating window_handle at all, meaning we would run the test in a background tab though.

Flags: needinfo?(jdescottes)

Alternatively, we could avoid updating the window_handle completely and run the test in a background tab.

Assignee: nobody → jdescottes
Status: NEW → ASSIGNED

(In reply to Julian Descottes [:jdescottes] from comment #2)

I assume we can also avoid updating window_handle at all, meaning we would run the test in a background tab though.

That was what we discussed during the review and as result bug 1764413 has been filed. So does it mean we should switch the order? If we now run tests in background tabs and do not have the screenshot feature available yet - that we could use to capture a tab's state - it will be harder to investigate intermittent failures.

I think that after each test we should close all the open tabs and windows so that just one tab remains. That would be in alignment with the WebDriver HTTP session handling in wdspec tests. I assume that the latter doesn't kick-in because we are not making use of the session / current_session fixtures?

Flags: needinfo?(jdescottes)
See Also: → 1764413

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #4)

(In reply to Julian Descottes [:jdescottes] from comment #2)

I assume we can also avoid updating window_handle at all, meaning we would run the test in a background tab though.

That was what we discussed during the review and as result bug 1764413 has been filed. So does it mean we should switch the order? If we now run tests in background tabs and do not have the screenshot feature available yet - that we could use to capture a tab's state - it will be harder to investigate intermittent failures.

Yes, I'm only stating the options available to fix the issue here, but note that it's not what I pushed to phabricator. My patch keeps the behavior and simply restores the state before closing the tab using BiDi's browsingContext.close

I think that after each test we should close all the open tabs and windows so that just one tab remains. That would be in alignment with the WebDriver HTTP session handling in wdspec tests. I assume that the latter doesn't kick-in because we are not making use of the session / current_session fixtures?

We do use current_session in the new_tab fixture, and I think that's part of the issue.

Flags: needinfo?(jdescottes)
Has Regression Range: --- → yes
Pushed by jdescottes@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/4c7ed5a5ab7e
[wdspec] new_tab fixture should restore the webdriver window_handle r=webdriver-reviewers,whimboo
Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/33644 for changes under testing/web-platform/tests
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 101 Branch
Upstream PR merged by moz-wptsync-bot
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: