1822974 - Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_title/iframe.py | expected OK

Status: RESOLVED DUPLICATE of bug 1783217

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

task 2023-03-17T06:36:33.371Z] 06:36:33     INFO - TEST-START | /webdriver/tests/get_title/iframe.py
[task 2023-03-17T06:36:33.441Z] 06:36:33     INFO - STDOUT: ============================= test session starts =============================
[task 2023-03-17T06:36:33.448Z] 06:36:33     INFO - STDOUT: platform win32 -- Python 3.9.10, pytest-7.0.1, pluggy-unknown -- Z:\task_167903346906393\build\venv\Scripts\python.exe
[task 2023-03-17T06:36:33.449Z] 06:36:33     INFO - STDOUT: rootdir: Z:\task_167903346906393\build
[task 2023-03-17T06:36:33.450Z] 06:36:33     INFO - STDOUT: plugins: asyncio-0.19.0
[task 2023-03-17T06:36:33.451Z] 06:36:33     INFO - STDOUT: asyncio: mode=strict
[task 2023-03-17T06:36:33.452Z] 06:36:33     INFO - STDOUT: collecting ... 
[task 2023-03-17T06:36:33.463Z] 06:36:33     INFO - STDOUT: collected 5 items
[task 2023-03-17T06:36:33.469Z] 06:36:33     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/get_title/iframe.py::test_no_iframe 
[task 2023-03-17T06:36:33.472Z] 06:36:33     INFO - PID 5368 | 1679034993470	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_167903346906 ... ata\\Local\\Temp\\tmpqauahrtu.mozrunner"], "binary": "Z:\\task_167903346906393\\build\\application\\firefox\\firefox.exe"}}}}
[task 2023-03-17T06:36:33.472Z] 06:36:33     INFO - PID 5368 | 1679034993470	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2023-03-17T06:36:33.473Z] 06:36:33     INFO - PID 5368 | 1679034993470	geckodriver::capabilities	DEBUG	Found version 113.0a1
[task 2023-03-17T06:36:33.473Z] 06:36:33     INFO - PID 5368 | 1679034993471	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_167903346906393\\AppData\\Local\\Temp\\tmpqauahrtu.mozrunner\\user.geckodriver_backup"
[task 2023-03-17T06:36:33.484Z] 06:36:33     INFO - PID 5368 | 1679034993484	mozrunner::runner	INFO	Running command: "Z:\\task_167903346906393\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_167903346906393\\AppData\\Local\\Temp\\tmpqauahrtu.mozrunner" "-no-remote"
[task 2023-03-17T06:36:33.487Z] 06:36:33     INFO - PID 5368 | 1679034993486	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2023-03-17T06:36:33.488Z] 06:36:33     INFO - PID 5368 | 1679034993486	geckodriver::browser	TRACE	Failed to open C:\Users\task_167903346906393\AppData\Local\Temp\tmpqauahrtu.mozrunner\MarionetteActivePort
[task 2023-03-17T06:36:33.488Z] 06:36:33     INFO - PID 5368 | 1679034993486	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-03-17T06:36:33.581Z] 06:36:33     INFO - PID 5368 | *** You are running in headless mode.
[task 2023-03-17T06:36:33.597Z] 06:36:33     INFO - PID 5368 | 1679034993596	geckodriver::browser	TRACE	Failed to open C:\Users\task_167903346906393\AppData\Local\Temp\tmpqauahrtu.mozrunner\MarionetteActivePort
[task 2023-03-17T06:36:33.598Z] 06:36:33     INFO - PID 5368 | 1679034993596	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-03-17T06:36:33.706Z] 06:36:33     INFO - PID 5368 | 1679034993706	geckodriver::browser	TRACE	Failed to open C:\Users\task_167903346906393\AppData\Local\Temp\tmpqauahrtu.mozrunner\MarionetteActivePort
[task 2023-03-17T06:36:33.708Z] 06:36:33     INFO - PID 5368 | 1679034993706	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-03-17T06:36:33.816Z] 06:36:33     INFO - PID 5368 | 1679034993816	geckodriver::browser	TRACE	Failed to open C:\Users\task_167903346906393\AppData\Local\Temp\tmpqauahrtu.mozrunner\MarionetteActivePort
[task 2023-03-17T06:36:33.817Z] 06:36:33     INFO - PID 5368 | 1679034993816	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-03-17T06:36:33.926Z] 06:36:33     INFO - PID 5368 | 1679034993926	geckodriver::browser	TRACE	Failed to open C:\Users\task_167903346906393\AppData\Local\Temp\tmpqauahrtu.mozrunner\MarionetteActivePort
[task 2023-03-17T06:36:33.927Z] 06:36:33     INFO - PID 5368 | 1679034993926	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-03-17T06:36:34.035Z] 06:36:34     INFO - PID 5368 | 1679034994035	geckodriver::browser	TRACE	Failed to open C:\Users\task_167903346906393\AppData\Local\Temp\tmpqauahrtu.mozrunner\MarionetteActivePort
[task 2023-03-17T06:36:34.037Z] 06:36:34     INFO - PID 5368 | 1679034994035	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-03-17T06:36:34.145Z] 06:36:34     INFO - PID 5368 | 1679034994145	geckodriver::browser	TRACE	Failed to open C:\Users\task_167903346906393\AppData\Local\Temp\tmpqauahrtu.mozrunner\MarionetteActivePort
[task 2023-03-17T06:36:34.147Z] 06:36:34     INFO - PID 5368 | 1679034994145	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-03-17T06:36:34.254Z] 06:36:34     INFO - PID 5368 | 1679034994255	geckodriver::browser	TRACE	Failed to open C:\Users\task_167903346906393\AppData\Local\Temp\tmpqauahrtu.mozrunner\MarionetteActivePort
[task 2023-03-17T06:36:34.256Z] 06:36:34     INFO - PID 5368 | 1679034994255	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2023-03-17T06:36:34.268Z] 06:36:34     INFO - PID 5368 | 1679034994267	Marionette	INFO	Marionette enabled
[task 2023-03-17T06:36:34.270Z] 06:36:34     INFO - PID 5368 | 1679034994269	Marionette	TRACE	Received observer notification final-ui-startup
[task 2023-03-17T06:36:34.271Z] 06:36:34     INFO - PID 5368 | 1679034994270	Marionette	INFO	Listening on port 57008
[task 2023-03-17T06:36:34.271Z] 06:36:34     INFO - PID 5368 | 1679034994271	Marionette	DEBUG	Marionette is listening
[task 2023-03-17T06:36:34.364Z] 06:36:34     INFO - PID 5368 | Read port: 57008
...

[task 2023-03-17T06:36:36.993Z] 06:36:36     INFO - PID 5368 | 1679034996990	webdriver::server	DEBUG	-> GET /session/5ad5041e-8113-4498-a072-ef00006a454d/window
[task 2023-03-17T06:36:36.994Z] 06:36:36     INFO - PID 5368 | 1679034996990	Marionette	DEBUG	0 -> [0,101,"WebDriver:GetWindowHandle",{}]
[task 2023-03-17T06:36:36.994Z] 06:36:36     INFO - PID 5368 | 1679034996991	Marionette	DEBUG	0 <- [1,101,null,{"value":"a5083d66-591e-4fa5-8821-d6253cb56073"}]
[task 2023-03-17T06:36:36.995Z] 06:36:36     INFO - PID 5368 | 1679034996991	webdriver::server	DEBUG	<- 200 OK {"value":"a5083d66-591e-4fa5-8821-d6253cb56073"}
[task 2023-03-17T06:36:36.996Z] 06:36:36     INFO - PID 5368 | 1679034996992	webdriver::server	DEBUG	-> GET /session/5ad5041e-8113-4498-a072-ef00006a454d/window/handles
[task 2023-03-17T06:36:36.996Z] 06:36:36     INFO - PID 5368 | 1679034996993	Marionette	DEBUG	0 -> [0,102,"WebDriver:GetWindowHandles",{}]
[task 2023-03-17T06:36:36.998Z] 06:36:36     INFO - PID 5368 | 1679034996993	Marionette	DEBUG	0 <- [1,102,null,["a5083d66-591e-4fa5-8821-d6253cb56073"]]
[task 2023-03-17T06:36:36.998Z] 06:36:36     INFO - PID 5368 | 1679034996993	webdriver::server	DEBUG	<- 200 OK {"value":["a5083d66-591e-4fa5-8821-d6253cb56073"]}
[task 2023-03-17T06:36:36.999Z] 06:36:36     INFO - PID 5368 | 1679034996994	webdriver::server	DEBUG	-> POST /session/5ad5041e-8113-4498-a072-ef00006a454d/window {"handle": "a5083d66-591e-4fa5-8821-d6253cb56073"}
[task 2023-03-17T06:36:36.999Z] 06:36:36     INFO - PID 5368 | 1679034996997	Marionette	DEBUG	0 -> [0,103,"WebDriver:SwitchToWindow",{"handle":"a5083d66-591e-4fa5-8821-d6253cb56073"}]
[task 2023-03-17T06:36:37.001Z] 06:36:37     INFO - PID 5368 | 1679034996997	Marionette	DEBUG	0 <- [1,103,null,{"value":null}]
[task 2023-03-17T06:36:37.002Z] 06:36:37     INFO - PID 5368 | 1679034996998	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-03-17T06:36:37.002Z] 06:36:37     INFO - PID 5368 | 1679034996999	webdriver::server	DEBUG	-> POST /session/5ad5041e-8113-4498-a072-ef00006a454d/window/rect {"width": 800, "height": 600}
[task 2023-03-17T06:36:37.003Z] 06:36:37     INFO - PID 5368 | 1679034997000	Marionette	DEBUG	0 -> [0,104,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2023-03-17T06:36:37.004Z] 06:36:37     INFO - PID 5368 | 1679034997000	Marionette	TRACE	Requested window geometry matches
[task 2023-03-17T06:36:37.005Z] 06:36:37     INFO - PID 5368 | 1679034997000	Marionette	DEBUG	0 <- [1,104,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2023-03-17T06:36:37.006Z] 06:36:37     INFO - PID 5368 | 1679034997001	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2023-03-17T06:36:37.007Z] 06:36:37     INFO - PID 5368 | 1679034997002	webdriver::server	DEBUG	-> POST /session/5ad5041e-8113-4498-a072-ef00006a454d/frame {"id": null}
[task 2023-03-17T06:36:37.007Z] 06:36:37     INFO - PID 5368 | 1679034997003	Marionette	DEBUG	0 -> [0,105,"WebDriver:SwitchToFrame",{"id":null}]
[task 2023-03-17T06:36:37.008Z] 06:36:37     INFO - PID 5368 | 1679034997004	Marionette	DEBUG	0 <- [1,105,null,{"value":null}]
[task 2023-03-17T06:36:37.009Z] 06:36:37     INFO - PID 5368 | 1679034997005	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-03-17T06:36:37.010Z] 06:36:37     INFO - PID 5368 | 1679034997008	webdriver::server	DEBUG	-> DELETE /session/5ad5041e-8113-4498-a072-ef00006a454d
[task 2023-03-17T06:36:37.011Z] 06:36:37     INFO - PID 5368 | 1679034997010	Marionette	DEBUG	0 -> [0,106,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2023-03-17T06:36:37.011Z] 06:36:37     INFO - PID 5368 | 1679034997011	Marionette	INFO	Stopped listening on port 57008
[task 2023-03-17T06:36:37.013Z] 06:36:37     INFO - PID 5368 | 1679034997012	Marionette	TRACE	[8589934597] MarionetteCommands actor destroyed for window id 10737418241
[task 2023-03-17T06:36:37.013Z] 06:36:37     INFO - PID 5368 | 1679034997012	Marionette	TRACE	[12] MarionetteCommands actor destroyed for window id 8589934594
[task 2023-03-17T06:36:37.015Z] 06:36:37     INFO - PID 5368 | 1679034997012	Marionette	TRACE	[8589934593] MarionetteCommands actor destroyed for window id 8589934596
[task 2023-03-17T06:36:37.015Z] 06:36:37     INFO - PID 5368 | 1679034997012	Marionette	TRACE	[13] MarionetteCommands actor destroyed for window id 8589934597
[task 2023-03-17T06:36:37.016Z] 06:36:37     INFO - PID 5368 | 1679034997012	Marionette	TRACE	[8589934595] MarionetteCommands actor destroyed for window id 8589934601
[task 2023-03-17T06:36:37.017Z] 06:36:37     INFO - PID 5368 | 1679034997012	Marionette	TRACE	[8589934594] MarionetteCommands actor destroyed for window id 8589934599
[task 2023-03-17T06:36:37.018Z] 06:36:37     INFO - PID 5368 | 1679034997012	Marionette	TRACE	[14] MarionetteCommands actor destroyed for window id 8589934602
[task 2023-03-17T06:36:37.019Z] 06:36:37     INFO - PID 5368 | 1679034997013	Marionette	TRACE	[8589934596] MarionetteCommands actor destroyed for window id 8589934604
[task 2023-03-17T06:36:37.019Z] 06:36:37     INFO - PID 5368 | 1679034997013	Marionette	TRACE	[15] MarionetteCommands actor destroyed for window id 8589934605
[task 2023-03-17T06:36:37.113Z] 06:36:37     INFO - PID 5368 | 1679034997113	Marionette	TRACE	Received observer notification quit-application
[task 2023-03-17T06:36:37.126Z] 06:36:37     INFO - PID 5368 | 1679034997125	Marionette	TRACE	Received observer notification quit-application
[task 2023-03-17T06:36:37.127Z] 06:36:37     INFO - PID 5368 | 1679034997126	Marionette	DEBUG	Marionette stopped listening
[task 2023-03-17T06:36:37.128Z] 06:36:37     INFO - PID 5368 | 1679034997127	Marionette	DEBUG	0 <- [1,106,null,{"cause":"shutdown","forced":false,"in_app":true}]
[task 2023-03-17T06:36:37.162Z] 06:36:37     INFO - PID 5368 | 1679034997166	webdriver::server	DEBUG	Teardown session
[task 2023-03-17T06:36:37.178Z] 06:36:37     INFO - PID 5368 | 1679034997181	Marionette	DEBUG	Closed connection 0
[task 2023-03-17T06:36:47.253Z] 06:36:47     INFO - PID 5368 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"ContentParent: id=1d9ade8a000","state":{"remoteTypePrefix":"prealloc"},"filename":"Z:/task_167902707902859/build/src/dom/ipc/ContentParent.cpp","lineNumber":3936,"stack":""}] Barrier: profile-before-change
[task 2023-03-17T06:36:52.133Z] 06:36:52     INFO - PID 5368 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.sys.mjs", 370))
[task 2023-03-17T06:37:28.380Z] 06:37:28     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_title/iframe.py | expected OK
[task 2023-03-17T06:37:28.380Z] 06:37:28     INFO - TEST-INFO took 55012ms
[task 2023-03-17T06:37:28.473Z] 06:37:28     INFO - Closing logging queue
[task 2023-03-17T06:37:28.477Z] 06:37:28     INFO - queue closed
[task 2023-03-17T06:37:28.989Z] 06:37:28     INFO - PID 3220 | 1679035048492	geckodriver	INFO	Listening on 127.0.0.1:60965
[task 2023-03-17T06:37:28.994Z] 06:37:28     INFO - Starting runner