Closed Bug 1533023 Opened 5 years ago Closed 5 years ago

Intermittent /webdriver/tests/get_element_attribute/user_prompts.py | test_dismiss_and_notify[capabilities0-alert-None] - setup error

Categories

(Remote Protocol :: Marionette, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, regression)

#[markdown(off)]
Filed by: rgurzau [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=232160027&repo=autoland

https://queue.taskcluster.net/v1/task/SS3po-9qQ6O8Z5MGKmD3Pg/runs/0/artifacts/public/logs/live_backing.log

14:16:15 INFO - TEST-PASS | /webdriver/tests/get_element_attribute/user_prompts.py | test_accept[capabilities0-alert-None]
14:16:15 INFO - TEST-PASS | /webdriver/tests/get_element_attribute/user_prompts.py | test_accept[capabilities0-confirm-True]
14:16:15 INFO - TEST-PASS | /webdriver/tests/get_element_attribute/user_prompts.py | test_accept[capabilities0-prompt-]
14:16:15 INFO - TEST-PASS | /webdriver/tests/get_element_attribute/user_prompts.py | test_accept_and_notify[capabilities0-alert-None]
14:16:15 INFO - TEST-PASS | /webdriver/tests/get_element_attribute/user_prompts.py | test_accept_and_notify[capabilities0-confirm-True]
14:16:15 INFO - TEST-PASS | /webdriver/tests/get_element_attribute/user_prompts.py | test_accept_and_notify[capabilities0-prompt-]
14:16:15 INFO - TEST-PASS | /webdriver/tests/get_element_attribute/user_prompts.py | test_dismiss[capabilities0-alert-None]
14:16:15 INFO - TEST-PASS | /webdriver/tests/get_element_attribute/user_prompts.py | test_dismiss[capabilities0-confirm-False]
14:16:15 INFO - TEST-PASS | /webdriver/tests/get_element_attribute/user_prompts.py | test_dismiss[capabilities0-prompt-None]
14:16:15 INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/get_element_attribute/user_prompts.py | test_dismiss_and_notify[capabilities0-alert-None] - setup error
14:16:15 INFO - capabilities = {'unhandledPromptBehavior': 'dismiss and notify'}
14:16:15 INFO - configuration = {'capabilities': {'moz:firefoxOptions': {'binary': 'Z:\task_1551879826\build\application\firefox\firefox.exe', 'prefs'...orm.test,xn--lve-6lad.www2.not-web-platform.test,www2.www.not-web-platform.test'}}}, 'host': '127.0.0.1', 'port': 4444}
14:16:15 INFO - request = <SubRequest 'session' for <Function 'test_dismiss_and_notify[capabilities0-alert-None]'>>
14:16:15 INFO -
14:16:15 INFO - @pytest.fixture(scope="function")
14:16:15 INFO - def session(capabilities, configuration, request):
14:16:15 INFO - """Create and start a session for a test that does not itself test session creation.
14:16:15 INFO -
14:16:15 INFO - By default the session will stay open after each test, but we always try to start a
14:16:15 INFO - new one and assume that if that fails there is already a valid session. This makes it
14:16:15 INFO - possible to recover from some errors that might leave the session in a bad state, but
14:16:15 INFO - does not demand that we start a new session per test."""
14:16:15 INFO - global _current_session
14:16:15 INFO -
14:16:15 INFO - # Update configuration capabilities with custom ones from the
14:16:15 INFO - # capabilities fixture, which can be set by tests
14:16:15 INFO - caps = copy.deepcopy(configuration["capabilities"])
14:16:15 INFO - caps.update(capabilities)
14:16:15 INFO - caps = {"alwaysMatch": caps}
14:16:15 INFO -
14:16:15 INFO - # If there is a session with different capabilities active, end it now
14:16:15 INFO - if _current_session is not None and (
14:16:15 INFO - caps != _current_session.requested_capabilities):
14:16:15 INFO - _current_session.end()
14:16:15 INFO - _current_session = None

Something is clearly wrong here:

14:15:53 INFO - PID 10836 | 1551881753678 mozrunner::runner INFO Running command: "Z:\task_1551879826\build\application\firefox\firefox.exe" "-marionette" "-foreground" "-no-remote" "-profile" "C:\Users\task_1551879826\AppData\Local\Temp\rust_mozprofile.ZlvugkK1i6M5"
14:15:53 INFO - PID 10836 | 1551881753679 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1:2828
14:15:54 INFO - PID 10836 | 1551881754785 mozrunner::runner DEBUG Killing process 436
14:15:54 INFO - PID 10836 | 1551881754785 webdriver::server DEBUG <- 500 Internal Server Error {"value":{"error":"unknown error","message":"permission denied","stacktrace":""}}

We start Firefox and 1s later we already kill the process. I wonder under which conditions this can happen. The relevant code is at least here:

https://searchfox.org/mozilla-central/rev/3e0f1d95fcf8832413457e3bec802113bdd1f8e8/testing/geckodriver/src/marionette.rs#1104-1141

If we would hit Some in the first if block I would expect to see output with the exit status. But given that this is not visible, the process is there but maybe Firefox doesn't start?

I could only explain the early return here with some weird behavior in now.elapsed(), and that it returns a value which is already larger than the timeout.

Andreas, do you have an idea?

Flags: needinfo?(ato)

“permission denied” usually indicates the inability to launch a
program when it is not executable. This is rare case where I think
I a Rust backtrace would be useful. If you can run the test
prepending RUST_BACKTRACE=1 that would give us a better indication
what exactly goes wrong, where.

Flags: needinfo?(ato)

I cannot. It is a very rare case and so far only happened a handfull of times. The only option I could see is to add the env variable by default by the marionette executor when running wdspec tests.

James would that be fine with you?

Flags: needinfo?(james)

Yes, no problem.

Flags: needinfo?(james)
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
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.