1768774 - Intermittent [tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/page_load_strategy.py | expected OK

Status: RESOLVED DUPLICATE of bug 1630162

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-05-11T03:36:30.497Z] 03:36:30     INFO - TEST-START | /webdriver/tests/new_session/page_load_strategy.py
[task 2022-05-11T03:36:30.549Z] 03:36:30     INFO - STDOUT: ============================= test session starts ==============================
[task 2022-05-11T03:36:30.549Z] 03:36:30     INFO - STDOUT: platform linux -- Python 3.6.9, pytest-6.1.1, py-1.5.2, pluggy-unknown -- /builds/worker/workspace/build/venv/bin/python
[task 2022-05-11T03:36:30.551Z] 03:36:30     INFO - STDOUT: rootdir: /builds/worker/workspace/build
[task 2022-05-11T03:36:30.552Z] 03:36:30     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2022-05-11T03:36:30.552Z] 03:36:30     INFO - STDOUT: collecting ... 
[task 2022-05-11T03:36:30.555Z] 03:36:30     INFO - STDOUT: collected 1 item
[task 2022-05-11T03:36:30.556Z] 03:36:30     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/page_load_strategy.py::test_pageLoadStrategy 
[task 2022-05-11T03:36:30.557Z] 03:36:30     INFO - PID 28994 | 1652240190556	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmpmd22lb_p.mozrunner"], "binary": "/builds/worker/workspace/build/application/firefox/firefox"}, "pageLoadStrategy": "eager"}}}
[task 2022-05-11T03:36:30.558Z] 03:36:30     INFO - PID 28994 | 1652240190556	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-05-11T03:36:30.559Z] 03:36:30     INFO - PID 28994 | 1652240190557	geckodriver::capabilities	DEBUG	Found version 102.0a1
[task 2022-05-11T03:36:30.559Z] 03:36:30     INFO - PID 28994 | 1652240190557	geckodriver::browser	DEBUG	Backing up prefs to "/tmp/tmpmd22lb_p.mozrunner/user.geckodriver_backup"
[task 2022-05-11T03:36:30.563Z] 03:36:30     INFO - PID 28994 | 1652240190563	mozrunner::runner	INFO	Running command: "/builds/worker/workspace/build/application/firefox/firefox" "--marionette" "--profile" "/tmp/tmpmd22lb_p.mozrunner" "-no-remote"
[task 2022-05-11T03:36:30.565Z] 03:36:30     INFO - PID 28994 | 1652240190564	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-05-11T03:36:30.566Z] 03:36:30     INFO - PID 28994 | 1652240190564	geckodriver::browser	TRACE	Failed to open /tmp/tmpmd22lb_p.mozrunner/MarionetteActivePort
[task 2022-05-11T03:36:30.566Z] 03:36:30     INFO - PID 28994 | 1652240190564	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-11T03:36:30.581Z] 03:36:30     INFO - PID 28994 | *** You are running in headless mode.
[task 2022-05-11T03:36:30.665Z] 03:36:30     INFO - PID 28994 | 1652240190664	geckodriver::browser	TRACE	Failed to open /tmp/tmpmd22lb_p.mozrunner/MarionetteActivePort
[task 2022-05-11T03:36:30.666Z] 03:36:30     INFO - PID 28994 | 1652240190664	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-11T03:36:30.692Z] 03:36:30     INFO - PID 28994 | 1652240190691	Marionette	INFO	Marionette enabled
[task 2022-05-11T03:36:30.693Z] 03:36:30     INFO - PID 28994 | 1652240190692	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-05-11T03:36:30.693Z] 03:36:30     INFO - PID 28994 | 1652240190692	Marionette	INFO	Listening on port 42138
[task 2022-05-11T03:36:30.694Z] 03:36:30     INFO - PID 28994 | 1652240190692	Marionette	DEBUG	Marionette is listening
[task 2022-05-11T03:36:30.765Z] 03:36:30     INFO - PID 28994 | Read port: 42138
[task 2022-05-11T03:36:30.777Z] 03:36:30     INFO - PID 28994 | 1652240190776	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:49634
[task 2022-05-11T03:36:30.786Z] 03:36:30     INFO - PID 28994 | 1652240190785	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:42138.
[task 2022-05-11T03:36:30.809Z] 03:36:30     INFO - PID 28994 | 1652240190808	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"pageLoadStrategy":"eager"}]
[task 2022-05-11T03:36:30.810Z] 03:36:30     INFO - PID 28994 | 1652240190809	Marionette	DEBUG	Waiting for initial application window
[task 2022-05-11T03:36:30.956Z] 03:36:30     INFO - PID 28994 | [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2022-05-11T03:36:31.396Z] 03:36:31     INFO - PID 28994 | 1652240191395	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2022-05-11T03:36:31.399Z] 03:36:31     INFO - PID 28994 | 1652240191398	RemoteAgent	TRACE	[30] Document already finished loading: about:blank
[task 2022-05-11T03:36:31.403Z] 03:36:31     INFO - PID 28994 | 1652240191402	Marionette	DEBUG	0 <- [1,1,null,{"sessionId":"46516002-1eee-4d5c-ab86-93c8cb45d6c6","capabilities":{"browserName":"firefox","browserVersion":"102.0 ... ownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-05-11T03:36:31.407Z] 03:36:31     INFO - PID 28994 | 1652240191404	webdriver::server	DEBUG	<- 200 OK {"value":{"sessionId":"46516002-1eee-4d5c-ab86-93c8cb45d6c6","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"102.0a1","moz:accessibilityChecks":false,"moz:buildID":"20220511030032","moz:geckodriverVersion":"0.31.0","moz:headless":true,"moz:processID":8172,"moz:profile":"/tmp/tmpmd22lb_p.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"pageLoadStrategy":"eager","platformName":"linux","platformVersion":"4.4.0-1014-aws","proxy":{},"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2022-05-11T03:36:31.407Z] 03:36:31     INFO - PID 28994 | 1652240191406	webdriver::server	DEBUG	-> DELETE /session/46516002-1eee-4d5c-ab86-93c8cb45d6c6
[task 2022-05-11T03:36:31.408Z] 03:36:31     INFO - STDOUT: PASSED
[task 2022-05-11T03:36:31.409Z] 03:36:31     INFO - PID 28994 | 1652240191408	Marionette	DEBUG	0 -> [0,2,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-05-11T03:36:31.410Z] 03:36:31     INFO - PID 28994 | 1652240191408	Marionette	INFO	Stopped listening on port 42138
[task 2022-05-11T03:36:31.439Z] 03:36:31     INFO - PID 28994 | 1652240191438	Marionette	TRACE	Received observer notification quit-application
[task 2022-05-11T03:36:31.441Z] 03:36:31     INFO - PID 28994 | 1652240191440	Marionette	TRACE	Received observer notification quit-application
[task 2022-05-11T03:36:31.441Z] 03:36:31     INFO - PID 28994 | 1652240191440	Marionette	DEBUG	Marionette stopped listening
[task 2022-05-11T03:36:31.442Z] 03:36:31     INFO - PID 28994 | 1652240191440	Marionette	DEBUG	0 <- [1,2,null,{"cause":"shutdown","forced":false}]
[task 2022-05-11T03:36:31.454Z] 03:36:31     INFO - PID 28994 | 1652240191453	webdriver::server	DEBUG	Teardown session
[task 2022-05-11T03:36:31.456Z] 03:36:31     INFO - PID 28994 | 1652240191455	Marionette	DEBUG	Closed connection 0
[task 2022-05-11T03:37:00.498Z] 03:37:00     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/page_load_strategy.py | expected OK
[task 2022-05-11T03:37:00.499Z] 03:37:00     INFO - TEST-INFO took 30002ms
[task 2022-05-11T03:37:00.616Z] 03:37:00     INFO - Closing logging queue
[task 2022-05-11T03:37:00.617Z] 03:37:00     INFO - queue closed
[task 2022-05-11T03:37:00.626Z] 03:37:00     INFO - PID 8352 | 1652240220624	geckodriver	INFO	Listening on 127.0.0.1:54614
[task 2022-05-11T03:37:00.626Z] 03:37:00     INFO - Starting runner
[task 2022-05-11T03:37:00.879Z] 03:37:00     INFO - TEST-START | /webdriver/tests/new_session/platform_name.py

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Shutdown hang of Firefox.

Comment 2

[BMO Automation]

Moving bug to Remote Protocol::Marionette component per bug 1815831.