Closed Bug 1758355 Opened 9 months ago Closed 3 months ago

Intermittent non-asan [tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/create_alwaysMatch.py | expected OK

Categories

(Testing :: geckodriver, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 1779759

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

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


[task 2022-03-07T12:50:29.169Z] 12:50:29     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_alwaysMatch.py::test_valid[test:extension-abc] 
[task 2022-03-07T12:50:29.169Z] 12:50:29     INFO - PID 7624 | 1646657429166	geckodriver::capabilities	DEBUG	Found version 99.0a1
[task 2022-03-07T12:50:29.170Z] 12:50:29     INFO - PID 7624 | 1646657429167	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_164665527541773\\AppData\\Local\\Temp\\tmp9punbe_b.mozrunner\\user.geckodriver_backup"
[task 2022-03-07T12:50:29.182Z] 12:50:29     INFO - PID 7624 | 1646657429182	mozrunner::runner	INFO	Running command: "Z:\\task_164665527541773\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_164665527541773\\AppData\\Local\\Temp\\tmp9punbe_b.mozrunner" "-no-remote"
[task 2022-03-07T12:50:29.185Z] 12:50:29     INFO - PID 7624 | 1646657429184	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-03-07T12:50:29.186Z] 12:50:29     INFO - PID 7624 | 1646657429184	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.186Z] 12:50:29     INFO - PID 7624 | 1646657429184	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:29.276Z] 12:50:29     INFO - PID 7624 | *** You are running in headless mode.
[task 2022-03-07T12:50:29.302Z] 12:50:29     INFO - PID 7624 | 1646657429303	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.304Z] 12:50:29     INFO - PID 7624 | 1646657429303	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:29.411Z] 12:50:29     INFO - PID 7624 | 1646657429412	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.413Z] 12:50:29     INFO - PID 7624 | 1646657429412	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:29.520Z] 12:50:29     INFO - PID 7624 | 1646657429520	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.522Z] 12:50:29     INFO - PID 7624 | 1646657429520	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:29.582Z] 12:50:29     INFO - PID 7624 | 1646657429588	Marionette	INFO	Marionette enabled
[task 2022-03-07T12:50:29.634Z] 12:50:29     INFO - PID 7624 | 1646657429634	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.636Z] 12:50:29     INFO - PID 7624 | 1646657429634	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:29.743Z] 12:50:29     INFO - PID 7624 | 1646657429743	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.745Z] 12:50:29     INFO - PID 7624 | 1646657429743	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:29.853Z] 12:50:29     INFO - PID 7624 | 1646657429854	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.856Z] 12:50:29     INFO - PID 7624 | 1646657429854	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:29.969Z] 12:50:29     INFO - PID 7624 | 1646657429969	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.970Z] 12:50:29     INFO - PID 7624 | 1646657429969	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:30.077Z] 12:50:30     INFO - PID 7624 | 1646657430078	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.079Z] 12:50:30     INFO - PID 7624 | 1646657430078	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:30.186Z] 12:50:30     INFO - PID 7624 | 1646657430187	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.189Z] 12:50:30     INFO - PID 7624 | 1646657430187	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:30.295Z] 12:50:30     INFO - PID 7624 | 1646657430296	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.297Z] 12:50:30     INFO - PID 7624 | 1646657430296	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:30.308Z] 12:50:30     INFO - PID 7624 | [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2022-03-07T12:50:30.409Z] 12:50:30     INFO - PID 7624 | 1646657430410	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.411Z] 12:50:30     INFO - PID 7624 | 1646657430410	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:30.525Z] 12:50:30     INFO - PID 7624 | 1646657430526	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.527Z] 12:50:30     INFO - PID 7624 | 1646657430526	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:30.641Z] 12:50:30     INFO - PID 7624 | 1646657430641	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.643Z] 12:50:30     INFO - PID 7624 | 1646657430641	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:30.757Z] 12:50:30     INFO - PID 7624 | 1646657430757	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.759Z] 12:50:30     INFO - PID 7624 | 1646657430757	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:30.872Z] 12:50:30     INFO - PID 7624 | 1646657430873	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.875Z] 12:50:30     INFO - PID 7624 | 1646657430873	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:30.995Z] 12:50:30     INFO - PID 7624 | 1646657430995	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.996Z] 12:50:30     INFO - PID 7624 | 1646657430995	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:31.110Z] 12:50:31     INFO - PID 7624 | 1646657431111	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:31.113Z] 12:50:31     INFO - PID 7624 | 1646657431111	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:31.226Z] 12:50:31     INFO - PID 7624 | 1646657431226	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:31.228Z] 12:50:31     INFO - PID 7624 | 1646657431226	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:31.342Z] 12:50:31     INFO - PID 7624 | 1646657431342	geckodriver::browser	TRACE	Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:31.344Z] 12:50:31     INFO - PID 7624 | 1646657431342	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-07T12:50:31.357Z] 12:50:31     INFO - PID 7624 | 1646657431365	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2022-03-07T12:50:31.367Z] 12:50:31     INFO - PID 7624 | 1646657431366	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2022-03-07T12:50:31.411Z] 12:50:31     INFO - PID 7624 | 1646657431424	Marionette	TRACE	All scripts recorded.
[task 2022-03-07T12:50:31.430Z] 12:50:31     INFO - PID 7624 | 1646657431429	Marionette	INFO	Listening on port 61158
[task 2022-03-07T12:50:31.432Z] 12:50:31     INFO - PID 7624 | 1646657431431	Marionette	DEBUG	Marionette is listening
[task 2022-03-07T12:50:31.460Z] 12:50:31     INFO - PID 7624 | Read port: 61158
[task 2022-03-07T12:50:31.464Z] 12:50:31     INFO - PID 7624 | 1646657431471	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:61161
[task 2022-03-07T12:50:31.475Z] 12:50:31     INFO - PID 7624 | 1646657431477	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:61158.
[task 2022-03-07T12:50:31.487Z] 12:50:31     INFO - PID 7624 | 1646657431486	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"test:extension":"abc"}]
[task 2022-03-07T12:50:31.500Z] 12:50:31     INFO - PID 7624 | 1646657431502	RemoteAgent	TRACE	[30] Document already finished loading: about:blank
[task 2022-03-07T12:50:31.517Z] 12:50:31     INFO - PID 7624 | 1646657431517	Marionette	DEBUG	0 <- [1,1,null,{"sessionId":"ed7c9ee7-7531-425d-b628-c9fba9be97eb","capabilities":{"browserName":"firefox","browserVersion":"99.0a ... ownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"test:extension":"abc","proxy":{}}}]
[task 2022-03-07T12:50:31.530Z] 12:50:31     INFO - PID 7624 | 1646657431526	webdriver::server	DEBUG	<- 200 OK {"value":{"sessionId":"ed7c9ee7-7531-425d-b628-c9fba9be97eb","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"99.0a1","moz:accessibilityChecks":false,"moz:buildID":"20220307093830","moz:geckodriverVersion":"0.30.0","moz:headless":true,"moz:processID":804,"moz:profile":"C:\\Users\\task_164665527541773\\AppData\\Local\\Temp\\tmp9punbe_b.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"windows","platformVersion":"10.0","proxy":{},"setWindowRect":true,"strictFileInteractability":false,"test:extension":"abc","timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2022-03-07T12:50:31.531Z] 12:50:31     INFO - STDOUT: PASSED
[task 2022-03-07T12:50:31.532Z] 12:50:31     INFO - PID 7624 | 1646657431529	webdriver::server	DEBUG	-> DELETE /session/ed7c9ee7-7531-425d-b628-c9fba9be97eb
[task 2022-03-07T12:50:31.533Z] 12:50:31     INFO - PID 7624 | 1646657431532	Marionette	DEBUG	0 -> [0,2,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-03-07T12:50:31.534Z] 12:50:31     INFO - PID 7624 | 1646657431533	Marionette	INFO	Stopped listening on port 61158
[task 2022-03-07T12:50:31.642Z] 12:50:31     INFO - PID 7624 | 1646657431645	Marionette	TRACE	Received observer notification quit-application
[task 2022-03-07T12:50:31.647Z] 12:50:31     INFO - PID 7624 | 1646657431645	Marionette	TRACE	Received observer notification quit-application
[task 2022-03-07T12:50:31.648Z] 12:50:31     INFO - PID 7624 | 1646657431645	Marionette	DEBUG	Marionette stopped listening
[task 2022-03-07T12:50:31.659Z] 12:50:31     INFO - PID 7624 | 1646657431658	Marionette	DEBUG	0 <- [1,2,null,{"cause":"shutdown","forced":false}]
[task 2022-03-07T12:50:31.695Z] 12:50:31     INFO - PID 7624 | 1646657431695	webdriver::server	DEBUG	Teardown session
[task 2022-03-07T12:50:31.697Z] 12:50:31     INFO - PID 7624 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-07T12:50:31.702Z] 12:50:31     INFO - PID 7624 | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-07T12:50:31.703Z] 12:50:31     INFO - PID 7624 | 1646657431703	Marionette	DEBUG	Closed connection 0
[task 2022-03-07T12:50:32.597Z] 12:50:32     INFO - PID 7624 | JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 71: AbortError: IOUtils: Shutting down and refusing additional I/O tasks
[task 2022-03-07T12:50:34.393Z] 12:50:34     INFO - PID 7624 | Waiting in WillDestroyCurrentMessageLoop for pid 828
[task 2022-03-07T12:50:37.615Z] 12:50:37     INFO - PID 7624 | Waiting in WillDestroyCurrentMessageLoop for pid 1732
[task 2022-03-07T12:50:37.631Z] 12:50:37     INFO - PID 7624 | Waiting in WillDestroyCurrentMessageLoop for pid 5232
[task 2022-03-07T12:50:37.631Z] 12:50:37     INFO - PID 7624 | Waiting in WillDestroyCurrentMessageLoop for pid 1852
[task 2022-03-07T12:50:37.632Z] 12:50:37     INFO - PID 7624 | Waiting in WillDestroyCurrentMessageLoop for pid 4908
[task 2022-03-07T12:50:37.632Z] 12:50:37     INFO - PID 7624 | Waiting in WillDestroyCurrentMessageLoop for pid 5988
[task 2022-03-07T12:50:44.190Z] 12:50:44     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/create_alwaysMatch.py | expected OK
[task 2022-03-07T12:50:44.190Z] 12:50:44     INFO - TEST-INFO took 365010ms
[task 2022-03-07T12:50:44.664Z] 12:50:44     INFO - Closing logging queue
[task 2022-03-07T12:50:44.664Z] 12:50:44     INFO - queue closed
[task 2022-03-07T12:50:45.185Z] 12:50:45     INFO - PID 2916 | 1646657444693	geckodriver	INFO	Listening on 127.0.0.1:49808
[task 2022-03-07T12:50:45.188Z] 12:50:45     INFO - Starting runner
[task 2022-03-07T12:50:45.971Z] 12:50:45     INFO - TEST-START | /webdriver/tests/new_session/create_firstMatch.py
See Also: → 1749851

Chris, could have the following Javascript failure delayed the shutdown of Firefox which finally ended in a timeout by the wptrunner?

JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 71: AbortError: IOUtils: Shutting down and refusing additional I/O tasks

If not this is a dupe of bug 1630162.

Flags: needinfo?(chutten)

That's in an observer notification, so I can't imagine it would have such an effect. :dthayer, the file contains some probes you own: do you know more about this?

Flags: needinfo?(chutten) → needinfo?(dothayer)
Status: NEW → RESOLVED
Closed: 3 months ago
Resolution: --- → DUPLICATE

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

Chris, could have the following Javascript failure delayed the shutdown of Firefox which finally ended in a timeout by the wptrunner?

JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 71: AbortError: IOUtils: Shutting down and refusing additional I/O tasks

(In reply to Chris H-C :chutten from comment #2)

That's in an observer notification, so I can't imagine it would have such an effect. :dthayer, the file contains some probes you own: do you know more about this?

This particular issue got actually fixed by bug 1779759.

Given since no more failure occurred I would tend to mark it as dupe of that bug.

Flags: needinfo?(dothayer)
You need to log in before you can comment on or make changes to this bug.